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 的处理能力。但是我们可以通过其他手段来处理这个问题，比如将大事务进程拆分等。
