oracle数据库A RAC node crash due to ora-00481
这是某个客户的案例，这里分享给大家! 在2015/1/13号凌晨3:44分左右，XXXX集群数据库的节点1出现出现crash。
通过分析XXXX1节点的告警日志，我们发现如下内容：
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
.......省略部分内容
Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lms1_27001440.trc:
ORA-00481: LMON process terminated with error
Tue Jan 13 03:44:43 2015
System state dump is made for local instance
System State dumped to trace file /home/oracle/app/admin/XXXX/bdump/XXXX1_diag_28246956.trc
Tue Jan 13 03:44:43 2015
Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lmd0_27198128.trc:
ORA-00481: LMON process terminated with error
Tue Jan 13 03:44:43 2015
Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_mman_28378004.trc:
ORA-00481: LMON process terminated with error
Tue Jan 13 03:44:43 2015
Errors in file /home/oracle/app/admin/XXXX/bdump/XXXX1_lck0_25952674.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 的LMON进程，其中作用主要是监控RAC的GES信息，当然其作用不仅仅局限于此，还负责检查集群中各个Node的健康情况，当有节点出现故障是，负责进行reconfig以及GRD(global resource Directory)的恢复等等。我们知道RAC的脑裂机制，如果IO fencing是Oracle本身来完成，也就是说由Clusterware来完成。那么LMON进程检查到实例级别出现脑裂时，会通知Clusterware来进行脑裂操作，然而其并不会等待Clusterware的处理结果。当等待超过一定时间，那么LMON进程会自动触发IMR(instance membership recovery)，这实际上也就是我们所说的Instance membership reconfig。
从上述的日志分析，我们可以看出，节点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
rcvr: id 9 orapid 15 ospid 26149404
.......
.......
rcvr: id 7 orapid 13 ospid 17105074
rcvr: id 16 orapid 22 ospid 29033450
send proxy: id 1 ndst 1 (1:1 )
send proxy: id 9 ndst 1 (1:9 )
.......
.......
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:
.......
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；同时，我们也知道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
.......
rcvr: id 7 orapid 13 ospid 17105074
rcvr: id 16 orapid 22 ospid 29033450
send proxy: id 1 ndst 1 (1:1 )
send proxy: id 9 ndst 1 (1:9 )
.......
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终止掉。在LMON进程被强制终止掉之前，触发了一个process 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
通过上述的分析，我们可以看到ORA-00481错误的产生是关键，而这个错误是LMON进程产生的。
对于ORA-00481错误来讲，根据Oracle MOS文档（1950963.1）描述，通常有如下几种可能性的原因：
1）实例无法获得LE（Lock Elements）锁
2）RAC流控机制的 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
我们从上述红色部分内容可以看出，tickets是足够的，因此我们也可以排除第2种情况。换句话讲，该ORA-00481错误的产生，本身并不是Oracle RAC的配置问题导致。
对于LMON检查到DRM操作出现timeout，最后导致实例crash。timeout的原因通常有如下几种：
1）操作系统Load极高，例如CPU极度繁忙，导致进程无法获得CPU资源
2）进程本身处理异常，比如进程挂起
3）网络问题，比如数据库节点之间通信出现异常
4）DRM本身机制的不完善
5）Oracle DRM Bug
从上面的信息来看，系统在出现异常时，操作系统的Load是很低的，因此第一点我们可以直接排除。
我们现在的目的是需要分析出LMON检查到了什么异常，以及为什么会出现异常。LMD进程在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)
Dump of memory from 0x07000014022E9320 to 0x07000014022E9528
......
7000014022E9520 00000000 00000000 [........]
(FOB) flags=67 fib=7000013c30cedf0 incno=0 pending i/o cnt=0
fname=/oradata2/XXXX/control03.ctl
fno=2 lblksz=16384 fsiz=1626
(FOB) flags=67 fib=7000013c30cea50 incno=0 pending i/o cnt=0
fname=/oradata1/XXXX/control02.ctl
fno=1 lblksz=16384 fsiz=1626
(FOB) flags=67 fib=7000013c30ce6b0 incno=0 pending i/o cnt=0
fname=/oradata1/XXXX/control01.ctl
fno=0 lblksz=16384 fsiz=1626
----------------------------------------
SO: 7000014036e36a8, type: 19, owner: 700001406331850, flag: INIT/-/-/0x00
GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 flags=0x0 inc=68
outq=0 sndq=0 opid=5 prmb=0x0
mbg[i]=(158041 85020) mbg[b]=(3534178 0) mbg[r]=(0 0)
fmq[i]=(20 1) fmq[b]=(5 0) fmq[r]=(0 0)
mop[s]=1 mop[q]=3692218 pendq=0 zmbq=0
nonksxp_recvs=0
------------process 0x7000014036e36a8--------------------
proc version : 0
Local node : 0
pid : 10682988
lkp_node : 0
svr_mode : 0
proc state : KJP_NORMAL
Last drm hb acked : 0
Total accesses : 2
Imm. accesses : 1
Locks on ASTQ : 0
Locks Pending AST : 0
Granted locks : 0
AST_Q:
PENDING_Q:
GRANTED_Q:
----------------------------------------
SO: 7000014036efd68, type: 19, owner: 7000014036e36a8, flag: INIT/-/-/0x00
----------------------------------------
SO: 70000136e79f658, type: 18, owner: 7000014036efd68, flag: INIT/-/-/0x00
----------enqueue 0x70000136e79f658------------------------
lock version : 1
Owner node : 1
grant_level : KJUSEREX
req_level : KJUSEREX
bast_level : KJUSEREX
notify_func : 0
resp : 70000140c6d9d40
procp : 7000014036efd68
pid : 0
proc version : 0
oprocp : 0
opid : 0
group lock owner : 0
xid : 0000-0000-00000000
dd_time : 0.0 secs
dd_count : 0
timeout : 0.0 secs
On_timer_q? : N
On_dd_q? : N
lock_state : GRANTED
Open Options :
Convert options :
History : 0x9c8d
Msg_Seq : 0x1
res_seq : 2
valblk : 0x00000000000000000000000000000000 .
----------resource 0x70000140c6d9d40----------------------
resname : [0x19][0x2],[RS]
Local node : 0
dir_node : 0
master_node : 0
hv idx : 122
hv last r.inc : 68
current inc : 68
hv status : 0
hv master : 0
open options :
grant_bits : KJUSERNL KJUSEREX
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 1 0 0 0 0 1
val_state : KJUSERVS_DUBVALUE
valblk : 0x00000000000000000000000000000000 .
access_node : 1
vbreq_state : 0
state : x0
resp : 70000140c6d9d40
On Scan_q? : N
Total accesses: 132825
Imm. accesses: 123137
Granted_locks : 1
Cvting_locks : 1
value_block: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 70000136e79f658 gl KJUSEREX rp 70000140c6d9d40 [0x19][0x2],[RS]
master 0 owner 1 bast 0 rseq 2 mseq 0x1 history 0x9c8d
open opt
CONVERT_Q:
lp 700001403a3d0c0 gl KJUSERNL rl KJUSEREX rp 70000140c6d9d40 [0x19][0x2],[RS]
master 0 pid 25428644 bast 0 rseq 3 mseq 0 history 0x9a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
Rdomain number is 0
----------------------------------------
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,我们可以发现为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)
Dump of memory from 0x07000014072E8460 to 0x07000014072E8668
7000014072E8460 00000007 00000000 07000014 036E30E8 [.............n0.]
......
7000014072E8660 00000000 00000000 [........]
----------------------------------------
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
.......
----------------------------------------
SO: 7000013c2f51f28, type: 41, owner: 7000014074a73d8, flag: INIT/-/-/0x00
(dummy) nxc=0, nlb=0
----------------------------------------
SO: 7000014035cb2f8, type: 11, owner: 700001405330198, flag: INIT/-/-/0x00
(broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 700001405330198,
event: 6, 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: 7000014036e3ba0, type: 19, owner: 700001405330198, flag: INIT/-/-/0x00
GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 flags=0x0 inc=68
outq=0 sndq=1 opid=6 prmb=0x0
mbg[i]=(0 55) mbg[b]=(11085 217185741) mbg[r]=(0 0)
fmq[i]=(30 14) fmq[b]=(20 5) fmq[r]=(0 0)
mop[s]=224759292 mop[q]=216634842 pendq=0 zmbq=0
nonksxp_recvs=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
AST_Q:
PENDING_Q:
GRANTED_Q:
KJM HIST LMD0:
7:0 6:1 10:31:0 9:31:3 11:1 15:1 12:78181 7:0 6:0 10:31:1
9:31:2 11:1 15:1 12:78106 7:1 6:0 10:31:0 9:31:2 11:2 15:0
12:78805 7:0 6:0 10:31:1 9:31:2 11:1 15:1 12:78194 7:0 6:0
10:31:1 9:31:2 11:1 15:0 12:78177 7:0 6:0 10:31:1 9:31:2 11:1
15:0 12:78176 7:0 6:1 10:31:0 9:31:2 11:1 15:1 12:78890 7:1
6:0 10:31:0 9:31:2 11:2 15:0 12:78177 7:0 6:1 10:31:0 9:31:3
11:1 15:0 12:78180 7:0
DEFER MSG QUEUE ON LMD0 IS EMPTY
SEQUENCES:
0:0.0 1:283096258.0
----------------------------------------
SO: 7000014054d78a0, type: 3, owner: 700001405330198, flag: INIT/-/-/0x00
(call) sess: cur 7000014074a73d8, rec 0, usr 7000014074a73d8; depth: 0
----------------------------------------
SO: 7000014036e30e8, type: 16, owner: 700001405330198, flag: INIT/-/-/0x00
(osp req holder)
从LMD 进程本身的进程dump信息来看，似乎并无异常。从LMON和LMD进程的process dump来看，进程本身状态是正常的。因此我们可以排除进程挂起导致出现Timeout的可能性。
我们可以看到LMD进程一直在等待ges remote message，很明显这是和另外一个数据库节点进行通信；因此我们要分析问题的根本原因，还需要分析节点2数据库实例的一些信息。
首先我们来分析节点2实例的数据库告警日志，如下：
Tue Jan 13 02:26:13 2015
Thread 2 advanced to log sequence 47410 (LGWR switch)
Current log# 7 seq# 47410 mem# 0: /redolog/XXXX/redo0701.log
Current log# 7 seq# 47410 mem# 1: /newredolog/XXXX/redo0703.log
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
Tue Jan 13 03:44:48 2015
LMS 0: 0 GCS shadows cancelled, 0 closed
......
LMS 5: 0 GCS shadows cancelled, 0 closed
Tue Jan 13 03:44:48 2015
LMS 9: 3 GCS shadows cancelled, 0 closed
Set master node info
Submitted all remote-enqueue requests
Dwn-cvts replayed, VALBLKs dubious
All grantable enqueues granted
Post SMON to start 1st pass IR
Tue Jan 13 03:44:49 2015
Instance recovery: looking for dead threads
Tue Jan 13 03:44:49 2015
Beginning instance recovery of 1 threads
Tue Jan 13 03:44:50 2015
LMS 6: 282848 GCS shadows traversed, 0 replayed
Tue Jan 13 03:44:50 2015
LMS 7: 284544 GCS shadows traversed, 0 replayed
.......
Tue Jan 13 03:44:51 2015
LMS 10: 283658 GCS shadows traversed, 0 replayed
Tue Jan 13 03:44:51 2015
LMS 11: 282777 GCS shadows traversed, 0 replayed
Tue Jan 13 03:44:51 2015
Submitted all GCS remote-cache requests
Fix write in gcs resources
Reconfiguration complete
Tue Jan 13 03:44:54 2015
parallel recovery started with 16 processes
Tue Jan 13 03:44:55 2015
Started redo scan
Tue Jan 13 03:44:55 2015
Completed redo scan
281591 redo blocks read, 4288 data blocks need recovery
Tue Jan 13 03:44:56 2015
Started redo application at
Thread 1: logseq 47935, block 1974207
Tue Jan 13 03:44:56 2015
Recovery of Online Redo Log: Thread 1 Group 4 Seq 47935 Reading mem 0
Mem# 0: /redolog/XXXX/redo0401.log
Mem# 1: /newredolog/XXXX/redo0403.log
Tue Jan 13 03:44:56 2015
Recovery of Online Redo Log: Thread 1 Group 5 Seq 47936 Reading mem 0
Mem# 0: /redolog/XXXX/redo0501.log
Mem# 1: /newredolog/XXXX/redo0503.log
Tue Jan 13 03:44:57 2015
Completed redo application
Tue Jan 13 03:44:57 2015
Completed instance recovery at
Thread 1: logseq 47936, block 270263, scn 6869096106270
4253 data blocks read, 4901 data blocks written, 281591 redo blocks read
Tue Jan 13 03:44:57 2015
Thread 1 advanced to log sequence 47937 (thread recovery)
Tue Jan 13 03:44:57 2015
Redo thread 1 internally disabled at seq 47937 (SMON)
Tue Jan 13 03:44:58 2015
ARC1: Archiving disabled thread 1 sequence 47937
Tue Jan 13 03:44:59 2015
Thread 2 advanced to log sequence 47411 (LGWR switch)
Current log# 8 seq# 47411 mem# 0: /redolog/XXXX/redo0801.log
Current log# 8 seq# 47411 mem# 1: /newredolog/XXXX/redo0803.log
Tue Jan 13 03:45:09 2015
SMON: Parallel transaction recovery tried
Tue Jan 13 03:45:53 2015
Reconfiguration started (old inc 70, new inc 72)
List of nodes:
0 1
Global Resource Directory frozen
Communication channels reestablished
* domain 0 valid = 1 according to instance 0
Tue Jan 13 03:45:53 2015
Master broadcasted resource hash value bitmaps
Non-local Process blocks cleaned out
Tue Jan 13 03:45:53 2015
LMS 0: 0 GCS shadows cancelled, 0 closed
从节点2的数据库告警日志来看，在3:44:48时间点，开始进行实例的reconfig操作，这与整个故障的时间点是符合的。告警日志中本身并无太多信息，我们接着分析节点2数据库实例的LMON进程trace信息：
*** 2015-01-13 03:18:53.006
Begin DRM(82933)
sent syncr inc 68 lvl 84937 to 0 (68,0/31/0)
synca inc 68 lvl 84937 rcvd (68.0)
sent syncr inc 68 lvl 84938 to 0 (68,0/34/0)
......
sent syncr inc 68 lvl 84968 to 0 (68,0/38/0)
synca inc 68 lvl 84968 rcvd (68.0)
End DRM(82933)
*** 2015-01-13 03:23:55.896
Begin DRM(82934)
sent syncr inc 68 lvl 84969 to 0 (68,0/31/0)
synca inc 68 lvl 84969 rcvd (68.0)
......
sent syncr inc 68 lvl 85000 to 0 (68,0/38/0)
synca inc 68 lvl 85000 rcvd (68.0)
End DRM(82934)
*** 2015-01-13 03:29:00.374
Begin DRM(82935)
sent syncr inc 68 lvl 85001 to 0 (68,0/31/0)
synca inc 68 lvl 85001 rcvd (68.0)
......
sent syncr inc 68 lvl 85011 to 0 (68,0/36/0)
synca inc 68 lvl 85011 rcvd (68.0)
*** 2015-01-13 03:29:10.511
sent syncr inc 68 lvl 85012 to 0 (68,0/38/0)
synca inc 68 lvl 85012 rcvd (68.0)
......
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)
kjxgfipccb: msg 0x110ffa0b8, mbo 0x110ffa0b0, type 22, ack 0, ref 0, stat 34
kjxgfipccb: Send cancelled, stat 34 inst 0, type 22, tkt (944,80)
kjxgfipccb: msg 0x11113be68, mbo 0x11113be60, type 22, ack 0, ref 0, stat 34
kjxgfipccb: Send cancelled, stat 34 inst 0, type 22, tkt (472,80)
kjxgrssvote: reconfig bitmap chksum 0xd7682cca cnt 1 master 1 ret 0
kjxggpoll: change poll time to 50 ms
* kjfcln: DRM aborted due to CGS rcfg.
* ** 2015-01-13 03:44:45.281
从上述LMON进程的日志来看，在故障时间点之前，数据库一直存在大量的DRM操作。上述红色部分的信息十分关键，首先节点进行reconfig时，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操作。
同时我们从* 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操作，DRM即为：Dynamic Resource Management。在Oracle 10gR1引入该特性之前，如果数据库需要更改某个资源的master节点，那么必须将数据库实例重启来完成。很显然，这一特性的引入无疑改变了一切。同时，从Oracle 10gR2开始，又引入了基于object/undo 级别的affinity。这里所谓的affinity，本质上是引入操作系统的概念，即对某个对象的亲和力程度；在数据库来看，即为对某个对象的访问频率程度。
在Oracle 10gR2版本中，默认情况下，当某个对象的被访问频率超过50时，而同时该对象的master又是其他节点时，那么Oracle则会触发DRM操作。在进程DRM操作的过程中，Oracle会将该资源的相关信息进行临时frozen，然后将该资源在其他节点进行unfrozen，然后更改资源的master节点。注意，这里临时frozen的资源其实是GRD（Global Resource Directory）中的资源。在整个DRM的过程之中，访问该资源的进程都将被临时挂起。因此，当系统出现DRM时，是很可能导致系统或进程出现异常的。
根据Oracle 文档的描述，当DRM触发较为频繁时，是很可能导致出现SYNC Timeout的，如下：
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核心进程的异常，最终导致了数据库实例被强行终止（当然，这本质上是为了保证数据的一致性）。目前客户已经屏蔽DRM，已经运行一周，暂时没有发现任何问题，有待进一步观察！
