0

Goldengate引发的数据库故障

李真旭 2019-07-24
48
摘要:Goldengate引发的数据库故障

2014年11月8日21点左右某客户的数据库集群出现swap耗尽的情况,导致数据库无法正常使用。检查数据库日志,发现相关的错误如下所示。

Sat Nov 08 20:50:23 CST 2014
Process startup failed, error stack:
Sat Nov 08 20:50:41 CST 2014
Errors in file /oracle/product/10.2.0/admin/xxx/bdump/xxx1_psp0_1835540.trc:
ORA-27300: OS system dependent operation:fork failed with status: 12
ORA-27301: OS failure message: Not enough space
ORA-27302: failure occurred at: skgpspawn3
Sat Nov 08 20:50:41 CST 2014
Process m000 died, see its trace file

 

根据数据库alert log的报错信息,我们可以知道从20:50左右开始出现ORA-27300、ORA-27301错误。根据Oracle MOS 文档Troubleshooting ORA-27300 ORA-27301 ORA-27302 errors [ID 579365.1]的描述可以知道,这个错误产生的原因就是内存不足导致。出现该错误的主机为Oracle RAC的1节点。该主机物理内存大小为96GB,Oracle SGA配置为30GB,PGA配置为6GB,操作系统Swap配置为16GB。

正常情况下,物理主机的内存是可以满足正常使用的。由于在20:56开始出现无法fork 进程,即使无法分配内存资源,说明在该时间点之前物理主机的内存使用已经出现问题了。通过Nmon 监控数据可以发现,实际上从当天下午18点左右,操作系统物理内存free memory就开始大幅下降如图13-5所示。

 

图13-5

从图13-5可以看出,数据库主机节点1的物理内存大约从18:01开始突然下降得很厉害,到18:14左右时,物理内存free Memory已经不足2GB了。而该主机的物理内存中,大部分为Process%所消耗,如图13-6所示。

 

图13-6

可以看到,该节点从18:20左右Process% 消耗的内存开始突然增加,到19:52时,基本上消耗了所有的物理内存。这里需要注意的,这里的Process% 内存消耗,是指该主机上的所有应用程序的进程消耗,包括Oracle的所有进程,以及其他应用程序的进程。

然而我根据Oracle 的AWR历史数据进行查询,发现并没有明显的会话消耗内存很高的情况。

SQL> select INSTANCE_NUMBER,SNAP_ID,STAT_NAME,value from dba_hist_osstat
 2  where stat_name like 'VM%' and snap_id > 13550 and snap_id < 13559
3   order by 1,2;
 
INSTANCE_NUMBER    SNAP_ID STAT_NAME                     VALUE
--------------- ---------- ---------------- ------------------
 1      13551 VM_IN_BYTES           4691725926408
 1      13551 VM_OUT_BYTES         14798577905664
 1      13552 VM_OUT_BYTES         14799491960832
 1      13552 VM_IN_BYTES           4691727376392
 1      13553 VM_OUT_BYTES         14800572719088
 1      13553 VM_IN_BYTES           4691727429624
 1      13554 VM_IN_BYTES           4691777949696
 1      13554 VM_OUT_BYTES         14820690083832
 1      13555 VM_OUT_BYTES         14857568350200
 1      13555 VM_IN_BYTES           4693160173560
 1      13556 VM_OUT_BYTES         14876324397048
 1      13556 VM_IN_BYTES           4695865995264
 1      13558 VM_OUT_BYTES         14882330329080
 1      13558 VM_IN_BYTES           4829460062208
 2      13551 VM_OUT_BYTES          2273165344776
 2      13551 VM_IN_BYTES            347420766216
 2      13552 VM_OUT_BYTES          2273229529104
 2      13552 VM_IN_BYTES            347420766216
 2      13553 VM_OUT_BYTES          2273286496272
 2      13553 VM_IN_BYTES            347420766216
 2      13554 VM_OUT_BYTES          2324453691408
 2      13554 VM_IN_BYTES            347433598968
 2      13555 VM_IN_BYTES            347559141384
 2      13555 VM_OUT_BYTES          2383075213320
 2      13556 VM_IN_BYTES            347674648584
 2      13556 VM_OUT_BYTES          2430000705552
 2      13557 VM_IN_BYTES            473531183112
 2      13557 VM_OUT_BYTES          2499316277256
 2      13558 VM_OUT_BYTES          2507250249744
 2      13558 VM_IN_BYTES            473575673856

 

看到上列数据不要惊讶,上列数据为累积数据,我们需要前后相减进行计算。

16:00 --17:00点:

SQL> select (4691727376392-4691725926408)/1024/1024 from dual; 
(4691727376392-4691725926408)/1024/1024
---------------------------------------
 1.3828125
SQL> select (14799491960832-14798577905664)/1024/1024 from dual; 
(14799491960832-14798577905664)/1024/1024
-----------------------------------------
 871.710938     ---换出的内存,单位为M.

 

17:00 --18:00点:

SQL> select (4691727429624-4691727376392)/1024/1024 from dual; 
(4691727429624-4691727376392)/1024/1024
---------------------------------------
 .050765991
SQL> select (14800572719088-14799491960832) /1024/1024 from dual; 
(14800572719088-14799491960832)/1024/1024
-----------------------------------------
 1030.69139    ---换出的内存,单位为M.

 

18:00 --19:00点:

SQL> select (4691777949696-4691727429624)/1024/1024 from dual; 
(4691777949696-4691727429624)/1024/1024
---------------------------------------
 48.1796951
SQL> select (14820690083832-14800572719088)/1024/1024 from dual; 
(14820690083832-14800572719088)/1024/1024
-----------------------------------------
 19185.4141   ---换出的内存,单位为M.

 

19:00 --20:00点:

SQL> select (4693160173560-4691777949696)/1024/1024 from dual; 
(4693160173560-4691777949696)/1024/1024
---------------------------------------
 1318.1914
SQL> select (14857568350200-14820690083832)/1024/1024 from dual;
(14857568350200-14820690083832)/1024/1024
-----------------------------------------
 35169.8555

 

20:00 --21:00点:

SQL> select (4695865995264-4693160173560)/1024/1024 from dual;
(4695865995264-4693160173560)/1024/1024
---------------------------------------
 2580.47266
 
SQL> select (14876324397048-14857568350200)/1024/1024 from dual;
(14876324397048-14857568350200)/1024/1024
-----------------------------------------
 17887.1602

 

从查询结果来看,Oracle 确实检查到了大量的换页操作,从18点~19点开始。但是我查询数据库18~21点的AWR数据却并没有发现有非常大的SQL操作。

SQL> select INSTANCE_NUMBER,snap_id,sum(SHARABLE_MEM)/1024/1024 from dba_hist_SQLstat
 2  where snap_id > 13550 and snap_id < 13558
3  group by INSTANCE_NUMBER,snap_id order by 1,2; 
INSTANCE_NUMBER    SNAP_ID SUM(SHARABLE_MEM)/1024/1024
--------------- ---------- ---------------------------
 1      13551                  28.9083166
 1      13552                  30.0213976
 1      13553                  28.7059259
 1      13554                  29.1716347
 1      13555                  29.1961374
 1      13556                  35.6658726
 2      13551                  19.5267887
 2      13552                  20.9447975
 2      13553                  23.5789862
 2      13554                  21.0861912
 2      13555                  22.5129433
 2      13556                  23.0631037
 2      13557                  21.7776823

 

据业务了解,数据库节点2节点每周六会进行一次批量的操作,这可能会产生影响。基于这一点,我们分析了节点2节点的nmon数据,发现内存使用率也非常高,如图13-7所示。

 

图13-7

从节点2的数据来看,内存的变化也是在18:00左右。然而变化的却是FScache%, Process%的指标是没有变化的。根据这一点可以判断,在该时间段内数据库产生了大量的归档日志,进而导致文件系统cache所占的内存比例大幅上升。进一步检查数据库发现确实这段时间产生的日志相对较多。

由于在该时间段产生了大量的操作,因此就可能就会产生大量的gc 等待。从节点2的awr数据来看,确实产生了大量的gc等待事件,如下所示。

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
gc buffer busy 11,042,588 20,687 2 28.1 Cluster
gc current block 2-way 1,113,439 16,922 15 23.0 Cluster
gc current block congested 19,115 10,336 541 14.1 Cluster
CPU time  9,914  13.5
gc cr multi block request 6,430,854 3,965 1 5.4 Cluster

 

那么这里有没有可能是由于大量gc 的产生,导致Oracle RAC的核心进程LMS等进程的负载增加,导致内存消耗的剧增呢?实际上,这一点是可以排除的。如果是Oracle的进程内存消耗较高,那么节点2的内存消耗变动,在18:00左右开始上升的应该是Process%,而不是FScache%.

到这里我们可以总结如下两点。

(1)节点1 内存耗光,主要是Process %消耗。

(2)节点2的内存的变化主要是发生在FScache%。

基于这两点,我们可以排除是数据库本身的进程消耗的大量内存导致swap被耗尽。在进一步分析时,发现于节点1部署了Oracle Goldengate同步软件,所以我怀疑极有可能是该软件导致。基于这个猜想,我进行了简单分析。如下是ogg的report信息。

2014-11-08 18:01:38  INFO    OGG-01026  Rolling over remote file ./dirdat/nt006444.
2014-11-08 18:03:43  INFO    OGG-01026  Rolling over remote file ./dirdat/nt006445.
 
........省略部分内容
2014-11-08 20:38:18  INFO    OGG-01026  Rolling over remote file ./dirdat/nt006551.
2014-11-08 20:52:02  INFO    OGG-01026  Rolling over remote file ./dirdat/nt006553.

 

我们可以发现,在故障时间段内该进程的操作明显要比其他时间段要频繁得多。从18点到20:38,Goldengate 抽取进程产生的trail文件超过100个。由于ogg本身也是部署在Oracle用户下,因此这也不难解释为什么节点1从该时间点开始内存的消耗会突然增加,而且nmon监控显示是Process%消耗增加。通过Nmon的监控数据,我们也可以发现paging的操作主要是goldengate的extract进程导致,如图13-8所示。

 

图13-8

Goldengate进程之所以会消耗大量的内存,是因为extract进程首先需要将数据读取到本地节点的内存中(即Goldengate的cachesize)。然后将cache中的数据解析为Goldengate特有的日志格式,并写入到trail文件中。通常情况下,当遭遇大事务时,Goldengate extract进程消耗的内存会大幅增加,因为Goldengate默认是以事务为单位(如果没有大事务拆分处理的话)。

上面数据是截取的部分内容。从时间点来看,和之前的nmon监控内存的变化是完全符合的。这可以完美解释为什么查询节点1的AWR数据发现从18点之后开始出现大量swap,但是数据库本身的却查不到内存消耗高的进程。

因此最终确认导致此次故障的最本质原因是由于Goldengate抽取进程消耗大量内存,最后产生大量的swap,进而最终影响了业务。

不过这里我并不推荐大家通过设置cachesize参数来控制goldengate 进程的内存消耗,这样有可能降低Goldengate 的处理能力。但是我们可以通过其他手段来处理这个问题,比如将大事务进程拆分等。


「喜欢文章,快来给作者赞赏墨值吧」

评论

0
0
Oracle
订阅
欢迎订阅Oracle频道,订阅之后可以获取最新资讯和更新通知。
墨值排行
今日本周综合
近期活动
全部
相关课程
全部