昨天晚上正在家看书,收到应用电话,某个业务的在线用户直线下跌,10分钟跌去了25%,第一反应是数据库有问题了,电话给负责这个数据库的兄弟,说是监控已经有告警,但是他当时不方便处理,那么,我来。
vpn登陆数据库,居然半天都连接不上主机,严重怀疑我家那个破铁通的网络,不过登陆2号节点没问题,还是比较快的。这个时候基本可以判断数据库出问题了;
等到漫长的登陆到数据库以后,发现数据库的load已经超过200,同时,swap使用超过了50%;这是一个由两个36G内存的服务器组建的oracle 10.2.0.4的RAC。
首先分析内存,确实free的只有180MB了,swap使用靠近8GB,系统的负载150左右。然后看看IO,本来这套系统的IO不咋地,以为是IO的问题,不过发现IO并不象想象中的那么高。首要问题还是内存。
这个机器有36GB内存,SGA给了17GB,当时的连接数,1300左右,根本不算高,内存却消耗殆尽。问题的原因,看起来是内存耗尽引起load高,但是内存又去那里了?
继续分析下去,cat /proc/meminfo 发现,这个系统的page tables使用接近10GB,而且,没有启用huge page。晚上没有机会去重启那个系统,只能等到今天白天了。
白天,我们修改好hugepage的使用,设置了vm.nr_hugepages 然后,尝试重启1号节点,先只重启一个节点,这基本上是我们干RAC数据库的时候的基本流程了,都养成习惯了。
重启以后,发现1号节点起不来。数据库直接给我一个错误:
Wed Aug 3 11:23:48 2011
Error: KGXGN polling error (15)
Wed Aug 3 11:23:48 2011
Errors in file /opt/oracle/admin/skycac/bdump/skycac1_lmon_19132.trc:
ORA-29702: error occurred in Cluster Group Service operation
LMON: terminating instance due to error 29702
这个错误有点意思,说是我们的Cluster可能有问题。
说实话,以前没碰到过这个错误,首先,我怀疑的是我的CRS有问题,看我的CRS status,显示的没什么异常。metalink了下,基本上,也没有太有用的信息。
然后,分析ocssd.log,看到如下信息:
- [ CSSD]2011-08-03 10:25:42.298 >USER: Copyright 2011, Oracle version 10.2.0.4.0
- [ clsdmt]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=db-192-168-173-98-skycacDBG_CSSD))
- [ CSSD]2011-08-03 10:25:42.298 >USER: CSS daemon log for node db-192-168-173-98-skycac, number 1, in cluster crs_skycac_sd
- [ CSSD]2011-08-03 10:25:42.311 [1779740768] >TRACE: clssscmain: local-only set to false
- [ CSSD]2011-08-03 10:25:42.324 [1779740768] >TRACE: clssnmReadNodeInfo: added node 1 (db-192-168-173-98-skycac) to cluster
- [ CSSD]2011-08-03 10:25:42.334 [1779740768] >TRACE: clssnmReadNodeInfo: added node 2 (db-192-168-173-99-skycac) to cluster
- [ CSSD]2011-08-03 10:25:42.342 [1137916224] >TRACE: clssnm_skgxninit: Compatible vendor clusterware not in use
- [ CSSD]2011-08-03 10:25:42.342 [1137916224] >TRACE: clssnm_skgxnmon: skgxn init failed
- [ CSSD]2011-08-03 10:25:42.347 [1779740768] >TRACE: clssnmNMInitialize: misscount set to (60)
- [ CSSD]2011-08-03 10:25:42.348 [1779740768] >TRACE: clssnmNMInitialize: Network heartbeat thresholds are: impending reconfig 30000 ms, reconfig start (misscount) 60000 ms
- [ CSSD]2011-08-03 10:25:42.356 [1779740768] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (0//dev/raw/raw1)
- [ CSSD]2011-08-03 10:25:42.356 [1137916224] >TRACE: clssnmvDPT: spawned for disk 0 (/dev/raw/raw1)
- [ CSSD]2011-08-03 10:25:42.360 [1779740768] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (1//dev/raw/raw43)
- [ CSSD]2011-08-03 10:25:42.363 [1148406080] >TRACE: clssnmvDPT: spawned for disk 1 (/dev/raw/raw43)
- [ CSSD]2011-08-03 10:25:42.366 [1779740768] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (2//dev/raw/raw85)
- [ CSSD]2011-08-03 10:25:42.370 [1086122304] >TRACE: clssnmvDPT: spawned for disk 2 (/dev/raw/raw85)
- [ CSSD]2011-08-03 10:25:44.373 [1086122304] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (2//dev/raw/raw85)
- [ CSSD]2011-08-03 10:25:44.376 [1158895936] >TRACE: clssnmvKillBlockThread: spawned for disk 2 (/dev/raw/raw85) initial sleep interval (1000)ms
- [ CSSD]2011-08-03 10:25:44.378 [1086122304] >TRACE: clssnmReadDskHeartbeat: node(2) is down. rcfg(18) wrtcnt(1609409) LATS(4294194160) Disk lastSeqNo(1609409)
- [ CSSD]2011-08-03 10:25:44.432 [1148406080] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (1//dev/raw/raw43)
- [ CSSD]2011-08-03 10:25:44.432 [1137916224] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (0//dev/raw/raw1)
- [ CSSD]2011-08-03 10:25:44.441 [1169385792] >TRACE: clssnmvKillBlockThread: spawned for disk 1 (/dev/raw/raw43) initial sleep interval (1000)ms
- [ CSSD]2011-08-03 10:25:44.442 [1779740768] >TRACE: clssnmFatalInit: fatal mode enabled
- [ CSSD]2011-08-03 10:25:44.442 [1179875648] >TRACE: clssnmvKillBlockThread: spawned for disk 0 (/dev/raw/raw1) initial sleep interval (1000)ms
- [ CSSD]2011-08-03 10:25:44.445 [1137916224] >TRACE: clssnmReadDskHeartbeat: node(2) is down. rcfg(18) wrtcnt(1609409) LATS(4294194230) Disk lastSeqNo(1609409)
- [ CSSD]2011-08-03 10:25:44.453 [1148406080] >TRACE: clssnmReadDskHeartbeat: node(2) is down. rcfg(18) wrtcnt(1609409) LATS(4294194240) Disk lastSeqNo(1609409)
- [ CSSD]2011-08-03 10:25:44.453 [1200855360] >TRACE: clssnmClusterListener: Listening on (ADDRESS=(PROTOCOL=tcp)(HOST=db-192-168-173-98-skycac-priv)(PORT=49895))
信息有点多,看起来也很奇怪,仔细看下的时候,发现其中有一行有意思(被我加粗的那行),cssd进程认为节点2宕机。
前面提到过,我检查过CRS的状态,CRS报告说,2号节点正常,该online的都online了。这个信息明显不对,有一个哥们谎报了。
这个时候,登陆到2号节点检查CRS,状态依然是正常的。登陆下sqlplus,我想看看2号节点的数据库发生了什么。居然给我hang了。
这个时候,再去检查下2号节点的alert log,发现其中出现了一段很有意思的信息:
- Wed Aug 3 09:48:13 2011
- Errors in file /opt/oracle/admin/skycac/udump/skycac2_ora_7662.trc:
- ORA-07445: exception encountered: core dump [kcbzib()+447] [SIGSEGV] [Address not mapped to object] [0x7FFF53865650] [] []
- Wed Aug 3 09:48:14 2011
- Trace dumping is performing id=[cdmp_20110803094814]
- Wed Aug 3 09:48:28 2011
- Process startup failed, error stack:
- Wed Aug 3 09:48:28 2011
- Errors in file /opt/oracle/admin/skycac/bdump/skycac2_psp0_15392.trc:
- ORA-27300: OS system dependent operation:fork failed with status: 12
- ORA-27301: OS failure message: Cannot allocate memory
- ORA-27302: failure occurred at: skgpspawn3
- Wed Aug 3 09:48:28 2011
- Errors in file /opt/oracle/admin/skycac/udump/skycac2_ora_8035.trc:
- ORA-07445: exception encountered: core dump [kcbgcur()+22] [SIGSEGV] [Address not mapped to object] [0x7FFF7E3E1FF0] [] []
这个信息说,2号节点的instance出现过7445错误,而出现错误的时间,刚好是1号节点重启的时间。
现在,我可以大胆推测问题的原因了:
1:应用通知说,应用都停了,可以重启数据库了;
2:DBA开始关闭1号节点的instance,但是这个时候数据库连接没有释放完成,1号节点关闭,导致大量的连接漂向2号节点;
3:2号节点受不了如此高的负载,instance hang了。
4:CRS检查2号节点正常;
5:1号节点的CSSD启动的时候,发现2号down了;
6:1号节点的instance重启的时候,认为Cluster异常。
对了,最后的处理方式,这个要说明下,最后怎么解决的:
关闭2号节点的instance,hang住了;关闭2号节点的CRS,hang住了;reboot 2号节点;等到两个节点都重启以后,重新启动HA,CRS,收工。
近期评论