在2015年1月13日凌晨3:44左右，某客户的一套集群数据库的节点1出现crash。检查该节点的告警日志，我们发现了如下内容。
Tue Jan 13 03:44:43 2015 Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lmon_10682988.trc: ORA-00481: LMON process terminated with error Tue Jan 13 03:44:43 2015 USER: terminating instance due to error 481 Tue Jan 13 03:44:43 2015 Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lms0_27525728.trc: ORA-00481: LMON process terminated with error .......省略部分内容 Tue Jan 13 03:44:44 2015 Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lgwr_33489026.trc: ORA-00481: LMON process terminated with error Tue Jan 13 03:44:44 2015 Doing block recovery for file 94 block 613368 Tue Jan 13 03:44:45 2015 Shutting down instance (abort) License high water mark = 1023 Tue Jan 13 03:44:49 2015 Instance terminated by USER, pid = 19333184 Tue Jan 13 03:44:55 2015 Instance terminated by USER, pid = 33554510 Tue Jan 13 03:45:46 2015 Starting ORACLE instance (normal) sskgpgetexecname failed to get name
从上述的告警日志来看，在凌晨3:44:43时间点，节点1的LMON进程出现异常被终止，抛出ORA-00481错误。接着节点1的数据库实例被强行终止。对于Oracle RAC 数据库故障，我们在进行分析时，首先要对Oracle RAC的一些核心进程原理有所了解才行，这样才能深入本质。这里我们简单描述Oracle RAC的几个核心进程的基本原理，例如LMON、LMS和LMD等。
对于Oracle 的LMON进程，其作用主要是监控RAC的GES（Global Enqueue Service）信息。当然其作用不仅仅局限于此，还负责检查集群中各个Node的健康情况。当有节点出现故障的时候，LMON进程负责进行reconfig以及GRD（global resource Directory）的恢复等。
我们知道RAC的脑裂机制，如果IO fencing是Oracle本身来完成，也就是说由Clusterware来完成。那么当LMON进程检查到实例级别出现脑裂时，会通知Clusterware来进行脑裂操作，当然LMON进程其并不会等待Clusterware的处理结果。当等待超过一定时间，LMON进程会自动触发IMR（instance membership recovery），这实际上也就是我们所说的Instance membership reconfig。
既然提到LMON进程的检测机制，那么LMON如何去检查集群中每个节点的健康状态呢？其中主要分为如下几种。
（1）网络心跳 （主要是通过ping进行检测）。
（2）控制文件磁盘心跳，其实就是每个节点的CKPT进程每三秒更新一次控制文件的机制。
Oracle RAC核心进程LMD主要负责处理全局缓存服务（保持块缓冲区在实例间一致）处理锁管理器服务请求。它向一个队列发出资源请求，这个队列由LMS进程处理。同时LMD 还负责处理全局死锁的检测、解析，并监视全局环境中的锁超时（这就是为什么我们经常看到数据库alert log中LMD进程发现全局死锁的原因）。
如果是Oracle 11gR2 rac环境，那么还存在一个新的核心进程，即LMBH进程。该进程是Oracle 11R2版本引入的一个进程，该进程的主要作用是负责监控LMD、LMON、LCK和LMS等核心进程，防止这些Oracle核心后台进程spin（stuck）或被阻塞。该进程会定时地将监控的信息打印输出在相应的trace文件中，便于我们进行诊断。这也是11gR2一个亮点。当LMBH进程发现其他核心进程出现异常时，会尝试发起一些kill动作。如果一定时间内仍然无法解决，那么将触发保护，将实例强行终止掉，当然这是为了保证RAC节点数据的完整性和一致性。
从上述的日志分析，我们可以看出，节点1实例是被LMON进程强行终止的，而LMON进程由于本身出现异常才采取了这样的措施。那么节点1的LMON进程为什么会出现异常呢？通过分析节点1数据库实例LMON进程的trace 内容，我们可以看到如下内容。
*** 2015-01-13 03:44:18.067 kjfcdrmrfg: SYNC TIMEOUT (1295766, 1294865, 900), step 31 Submitting asynchronized dump request [28] KJC Communication Dump: state 0x5 flags 0x0 mode 0x0 inst 0 inc 68 nrcv 17 nsp 17 nrcvbuf 1000 reg_msg: sz 456 cur 1235 (s:0 i:1235) max 5251 ini 3750 big_msg: sz 8240 cur 263 (s:0 i:263) max 1409 ini 1934 rsv_msg: sz 8240 cur 0 (s:0 i:0) max 0 tot 1000 rcvr: id 1 orapid 7 ospid 27525728 ....... 略部分内容 send proxy: id 16 ndst 1 (1:16 ) GES resource limits: ges resources: cur 0 max 0 ini 39515 ges enqueues: cur 0 max 0 ini 59069 ges cresources: cur 4235 max 7721 gcs resources: cur 4405442 max 5727836 ini 7060267 gcs shadows: cur 4934515 max 6358617 ini 7060267 KJCTS state: seq-check:no timeout:yes waitticks:0x3 highload no ......省略部分内容 kjctseventdump-end tail 238 heads 0 @ 0 238 @ -744124571 sync() timed out - lmon exiting kjfsprn: sync status inst 0 tmout 900 (sec) kjfsprn: sync propose inc 68 level 85020 kjfsprn: sync inc 68 level 85020 kjfsprn: sync bitmap 0 1 kjfsprn: dmap ver 68 (step 0) ....... 略部分内容 DUMP state for lmd0 (ospid 27198128) DUMP IPC context for lmd0 (ospid 27198128) Dumping process 6.27198128 info:
从上面LMON进程的trace信息来看，LMON进程检测到了DRM在进行sync同步时出现了timeout，最后LMON强制退出了。既然如此，那么我们应该继续分析为什么DRM会出现timeout。另外根据前面讲述的原理，Oracle DRM的操作主要进程是LMD进程来完成，那么我们来分析节点1实例的LMD进程的trace内容，是否能看出蛛丝马迹。
*** 2015-01-13 03:44:43.666 lmd abort after exception 481 KJC Communication Dump: state 0x5 flags 0x0 mode 0x0 inst 0 inc 68 nrcv 17 nsp 17 nrcvbuf 1000 reg_msg: sz 456 cur 1189 (s:0 i:1189) max 5251 ini 3750 big_msg: sz 8240 cur 261 (s:0 i:261) max 1409 ini 1934 rsv_msg: sz 8240 cur 0 (s:0 i:0) max 0 tot 1000 rcvr: id 1 orapid 7 ospid 27525728 ....... ......省略部分内容 send proxy: id 7 ndst 1 (1:7 ) send proxy: id 16 ndst 1 (1:16 ) GES resource limits: ges resources: cur 0 max 0 ini 39515 ges enqueues: cur 0 max 0 ini 59069 ges cresources: cur 4235 max 7721 gcs resources: cur 4405442 max 5727836 ini 7060267 gcs shadows: cur 4934515 max 6358617 ini 7060267 KJCTS state: seq-check:no timeout:yes waitticks:0x3 highload no GES destination context: GES remote instance per receiver context: GES destination context:
我们可以看到，当LMON进程遭遇ORA-00481错误之后，LMD进程也被强制abort终止掉了。从LMD 进程的trace文件来看，出现了tickets 等待超时的情况，而且日志中Oracle也告诉我们，在该故障时间点，系统负载并不高。
从上述内容来看，我们似乎并没有得到十分有价值信息。由于LMON进程被强制终止掉之前，触发了一个process dump，因此我们进一步来分析进程dump，继续寻找蛛丝马迹。
*** 2015-01-13 03:44:18.114 Dump requested by process [orapid=5] REQUEST:custom dump [2] with parameters [5][6][0][0] Dumping process info of pid[6.27198128] requested by pid[5.10682988] Dumping process 6.27198128 info: *** 2015-01-13 03:44:18.115 Dumping diagnostic information for ospid 27198128: OS pid = 27198128 loadavg : 1.71 1.75 2.33 swap info: free_mem = 13497.62M rsv = 96.00M alloc = 342.91M avail = 24576.00M swap_free = 24233.09M F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD 240001 A oracle 19530440 10682988 10 65 20 16ae3ea590 1916 03:44:18 - 0:00 /usr/bin/procstack 27198128 242001 T oracle 27198128 1 1 60 20 7412f4590 108540 Dec 29 - 569:20 ora_lmd0_XXXX1 procstack: open(/proc/27198128/ctl): Device busy *** 2015-01-13 03:44:18.420
LMD进程的processstate dmp 似乎也没有太多有价值的内容。不过我们至少可以肯定的是，系统的资源使用很正常。
通过上述的分析，我们可以看到ORA-00481错误的产生是关键，而这个错误是LMON进程产生的。ORA-00481错误在Oracle MOS文档（1950963.1）中有非常详细的描述，针对本文DRM操作没有结束的情况，一般有如下2种原因。
（1）实例无法获得LE（Lock Elements）锁。
（2）tickets不足。
根据文档描述，我们从数据库两个节点的LMS进程trace中没有发现如下的类似关键信息。
Start affinity expansion for pkey 81885.0 Expand failed: pkey 81885.0, 229 shadows traversed, 153 replayed 1 retries
因此，我们可以排除第一种可能性。我们从LMD进程的trace文件中可以看到如下类似信息。
GES destination context: Dest 1 rcvr 0 inc 68 state 0x10041 tstate 0x0 batch-type quick bmsg 0x0 tmout 0x20f0dd31 msg_in_batch 0 tkt total 1000 avl 743 sp_rsv 242 max_sp_rsv 250 seq wrp 0 lst 268971339 ack 0 snt 268971336 sync seq 0.268971339 inc 0 sndq enq seq 0.268971339 batch snds 546480 tot msgs 5070830 max sz 88 fullload 85 snd seq 546480 pbatch snds 219682271 tot msgs 267610831 sndq msg tot 225339578 tm (0 17706) sndq msg 0 maxlmt 7060267 maxlen 149 wqlen 225994573 sndq msg 0 start_tm 0 end_tm 0
这里的tkt total 表示目前数据库实例总的tickets数据为1000，当前可用的tickets为743. 因此我们可以排除ticket不足的导致DRM没有完成的情况。
换句话讲，上述ORA-00481错误的产生，本身并不是Oracle RAC的配置问题导致。对于LMON进程检查到DRM操作出现超时，最后导致实例崩溃。超时的原因通常有如下几种。
（1）操作系统Load极高，例如CPU极度繁忙，导致进程无法获得CPU资源。
（2）进程本身处理异常，比如进程挂起。
（3）网络问题，比如数据库节点之间通信出现异常。
（4）Oracle DRM Bug。
从上面的信息来看，系统在出现异常时，操作系统的Load是很低的，因此第一点我们可以直接排除。
我们现在的目的是需要分析出LMON进程检查到了什么异常，以及为什么会出现异常。LMON进程在abort之前进行了dump，那么是否能够从相关dump 中找到一些有价值的线索呢？
PROCESS 5: ---------------------------------------- SO: 700001406331850, type: 2, owner: 0, flag: INIT/-/-/0x00 (process) Oracle pid=5, calls cur/top: 7000014054d75e0/7000014054d75e0, flag: (6) SYSTEM int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 24 last post received-location: ksasnd last process to post me: 700001405330198 1 6 last post sent: 0 0 24 last post sent-location: ksasnd last process posted by me: 7000014023045d0 1 2 (latch info) wait_event=0 bits=0 Process Group: DEFAULT, pseudo proc: 70000140336dd88 O/S info: user: oracle, term: UNKNOWN, ospid: 10682988 OSD pid info: Unix process pid: 10682988, image: oracle@tpihxdb1 (LMON) ......省略部分内容 ---------------------------------------- SO: 7000014064d88c8, type: 4, owner: 700001406331850, flag: INIT/-/-/0x00 (session) sid: 1652 trans: 0, creator: 700001406331850, flag: (51) USR/- BSY/-/-/-/-/- DID: 0001-0005-00000006, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 0, prv: 0, SQL: 0, pSQL: 0, user: 0/SYS service name: SYS$BACKGROUND last wait for 'ges generic event' blocking sess=0x0 seq=35081 wait_time=158 seconds since wait started=0 =0, =0, =0 Dumping Session Wait History for 'ges generic event' count=1 wait_time=158 =0, =0, =0 ....... ---------------------------------------- SO: 7000013c2f52018, type: 41, owner: 7000014064d88c8, flag: INIT/-/-/0x00 (dummy) nxc=0, nlb=0 ---------------------------------------- SO: 7000014035cb1e8, type: 11, owner: 700001406331850, flag: INIT/-/-/0x00 (broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 700001406331850, event: 5, last message event: 70, last message waited event: 70, next message: 0(0), messages read: 1 channel: (7000014074b6298) system events broadcast channel scope: 2, event: 129420, last mesage event: 70, publishers/subscribers: 0/915, messages published: 1 ---------------------------------------- SO: 7000014054d75e0, type: 3, owner: 700001406331850, flag: INIT/-/-/0x00 (call) sess: cur 7000014064d88c8, rec 0, usr 7000014064d88c8; depth: 0 ---------------------------------------- SO: 7000014036e3060, type: 16, owner: 700001406331850, flag: INIT/-/-/0x00 (osp req holder)
从上面LMON进程本身的dump来看，节点1实例的LMON进程状态是正常的，最后发送消息给LMON进程的是SO: 700001405330198，SO即为state obejct。搜索该SO，我们可以发现为LMD进程。
PROCESS 6: ---------------------------------------- SO: 700001405330198, type: 2, owner: 0, flag: INIT/-/-/0x00 (process) Oracle pid=6, calls cur/top: 7000014054d78a0/7000014054d78a0, flag: (6) SYSTEM int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 104 last post received-location: kjmpost: post lmd last process to post me: 700001402307510 1 6 last post sent: 0 0 24 last post sent-location: ksasnd last process posted by me: 700001407305690 1 6 (latch info) wait_event=0 bits=0 Process Group: DEFAULT, pseudo proc: 70000140336dd88 O/S info: user: oracle, term: UNKNOWN, ospid: 27198128 (DEAD) OSD pid info: Unix process pid: 27198128, image: oracle@tpihxdb1 (LMD0) ......省略部分内容 ---------------------------------------- SO: 7000014008a8d00, type: 20, owner: 700001405330198, flag: -/-/-/0x00 namespace [KSXP] key = [ 32 31 30 47 45 53 52 30 30 30 00 ] ---------------------------------------- SO: 7000014074a73d8, type: 4, owner: 700001405330198, flag: INIT/-/-/0x00 (session) sid: 1651 trans: 0, creator: 700001405330198, flag: (51) USR/- BSY/-/-/-/-/- DID: 0000-0000-00000000, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 0, prv: 0, SQL: 0, pSQL: 0, user: 0/SYS service name: SYS$BACKGROUND last wait for 'ges remote message' blocking sess=0x0 seq=25909 wait_time=163023 seconds since wait started=62 waittime=40, loop=0, p3=0 Dumping Session Wait History for 'ges remote message' count=1 wait_time=163023 waittime=40, loop=0, p3=0 .......省略部分内容 ------------process 0x7000014036e3ba0-------------------- proc version : 0 Local node : 0 pid : 27198128 lkp_node : 0 svr_mode : 0 proc state : KJP_NORMAL Last drm hb acked : 0 Total accesses : 31515 Imm. accesses : 31478 Locks on ASTQ : 0 Locks Pending AST : 0 Granted locks : 2
从LMON和LMD进程的process dump来看，进程本身状态是正常的。因此我们可以排除进程挂起导致出现Timeout的可能性。同时我们可以看到LMD进程一直在等待ges remote message，很明显这是和另外一个数据库节点进行通信。因此我们要分析问题的根本原因，还需要分析节点2数据库实例的一些信息。
首先我们来分析节点2实例的数据库告警日志。
Tue Jan 13 03:39:14 2015 Timed out trying to start process PZ96. Tue Jan 13 03:44:44 2015 Trace dumping is performing id=[cdmp_20150113034443] Tue Jan 13 03:44:48 2015 Reconfiguration started (old inc 68, new inc 70) List of nodes: 1 Global Resource Directory frozen * dead instance detected - domain 0 invalid = TRUE Communication channels reestablished Master broadcasted resource hash value bitmaps Non-local Process blocks cleaned out
从节点2的数据库告警日志来看，在3:44:48时间点，实例开始进行reconfig操作，这与整个故障的时间点是符合的。告警日志中本身并无太多信息，我们接着分析节点2数据库实例的LMON进程trace信息。
*** 2015-01-13 03:18:53.006 Begin DRM(82933) ……省略部分内容 End DRM(82933) *** 2015-01-13 03:23:55.896 Begin DRM(82934) ……省略部分内容 End DRM(82934) *** 2015-01-13 03:29:00.374 Begin DRM(82935) .....省略部分内容 sent syncr inc 68 lvl 85020 to 0 (68,0/38/0) synca inc 68 lvl 85020 rcvd (68.0) *** 2015-01-13 03:44:45.191 kjxgmpoll reconfig bitmap: 1 *** 2015-01-13 03:44:45.191 kjxgmrcfg: Reconfiguration started, reason 1 kjxgmcs: Setting state to 68 0. *** 2015-01-13 03:44:45.222 Name Service frozen kjxgmcs: Setting state to 68 1. kjxgfipccb: msg 0x110fffe78, mbo 0x110fffe70, type 22, ack 0, ref 0, stat 34 kjxgfipccb: Send cancelled, stat 34 inst 0, type 22, tkt (1416,80) ……省略部分内容 kjxggpoll: change poll time to 50 ms * kjfcln: DRM aborted due to CGS rcfg. * ** 2015-01-13 03:44:45.281
从上述LMON进程的日志来看，在故障时间点之前，数据库一直存在大量的DRM操作。并且注意到节点进行reconfiguration时，reason 代码值为1。关于reason值，Oracle Metalink文档有如下描述。
Reason 0 = No reconfiguration Reason 1 = The Node Monitor generated the reconfiguration. Reason 2 = An instance death was detected. Reason 3 = Communications Failure Reason 4 = Reconfiguration after suspend
从reason =1 来看，数据库实例被强行终止重启也不是通信故障的问题。如果是通信的问题，那么reason值通常应该等于3．reason=1表明这是数据库节点自身监控时触发的reconfig操作。这也与我们前面分析节点1的日志的结论是符合的。
我们从* kjfcln: DRM aborted due to CGS rcfg. 这段关键信息也可以确认，CGS reconfig的原因也正是由于DRM操作失败导致。同时也可以看到，在3:29开始的Begin DRM（82935）操作，一直到3：44出现故障时，这个DRM操作都没有结束（如果结束，会出现End DRM（82935） 类似关键字）。
由此也不难看出，实际上，该集群数据库可能在3:29之后就已经出现问题了。这里简单补充一下Oracle DRM的原理： 在Oracle RAC环境中，当某个节点对某个资源访问频率较高时，而该资源的master节点是不是local节点时，那么可能会触发DRM（Dynamic Resource Management）操作。在Oracle 10gR1引入该特性之前，如果数据库需要更改某个资源的master节点，那么必须将数据库实例重启来完成。很显然，这一特性的引入无疑改变了一切。同时，从Oracle 10gR2开始，又引入了基于object/undo 级别的affinity。这里所谓的affinity，本质上是引入操作系统的概念，即用来表示某个对象的亲和力程度。在数据库来看，即为对某个对象的访问频率程度。
在Oracle 10gR2版本中，默认情况下，当某个对象的被访问频率超过50时，而同时该对象的master又是其他节点时，那么Oracle则会触发DRM操作来修改master节点，这样的好处是可以大幅降低gc grant之类的等待事件。在进程DRM操作的过程中，Oracle会将该资源的相关信息进行临时frozen，然后将该资源在其他节点进行unfrozen，然后更改资源的master节点。这里我们需要注意的是，这里frozen的资源其实是GRD（Global Resource Directory）中的资源。在整个DRM的过程之中，访问该资源的进程都将被临时挂起。正因为如此，当系统出现DRM操作时，很可能导致系统或进程出现异常的。
实际上关于Oracle DRM的Bug也非常多，尤其是Oracle 10gR2版本中。针对本次故障，我们基本上可以认定是如下的Bug导致。
Bug 6960699 - "latch: cache buffers chains" contention/ORA-481/kjfcdrmrfg: SYNC TIMEOUT/ OERI[kjbldrmrpst:!master] (ID 6960699.8) Dynamic ReMastering (DRM) can be too aggressive at times causing any combination of the following symptoms : - "latch: cache buffers chains" contention. - "latch: object queue header operation" contention - a RAC node can crash with and ora-481 / kjfcdrmrfg: SYNC TIMEOUT ... step 31 - a RAC node can crash with OERI[kjbldrmrpst:!master]
最后建议客户屏蔽Oracle DRM功能之后，经过监控发现运行了相当长一段时间后都没有出现类似问题。
通过这个RAC的案例分析，大家可能注意到，相关的集群日志非常多。在分析过程中，需要保持非常清晰的思路，才能基于问题将这些信息串联起来，最终成为定位和解决问题的重要信息。而事后基于问题的总结和研究，更加是巩固知识、带动我们成长的关键。希望大家能够从中学到故障分析、学习提升的思路和方法。
