昨天某个客户的一套双节rac其中一个节点crash,同时最后导致另外一个节点也hang住,只能shutdown abort. 且出现shutdown abort实例之后，还有部分进程无法通过kill -9 进行kill的情况。其中有lgwr，arch等进程. 首先我们来看下，在下午出现crash的节点的alert
昨天某个客户的一套双节rac其中一个节点crash,同时最后导致另外一个节点也hang住,只能shutdown abort.
且出现shutdown abort实例之后，还有部分进程无法通过kill -9 进行kill的情况。其中有lgwr，arch等进程.
首先我们来看下，在下午出现crash的节点的alert log信息：
?12345678910111213141516171819202122232425262728293031323334353637383940414243 tue apr 22 17:16:04 2014deleted oracle managed file /oa1/arch/authorcl/archivelog/2014_03_14/o1_mf_2_4878_9l51y1cc_.arcdeleted oracle managed file /oa1/arch/authorcl/archivelog/2014_03_14/o1_mf_2_4879_9l529hc6_.arcarchived log entry 10847 addedfor thread 1 sequence 5314 id 0xffffffffae21a60f dest 1:tue apr 22 17:25:05 2014ipc send timeout detected. sender: ospid 27573 [oracle@xhdb-server3 (lmon)]receiver: inst 2 binc 95439 ospid 13752communications reconfiguration: instance_number 2tue apr 22 17:26:49 2014lmon (ospid: 27573) has not called a waitfor 89 secs.errors in file /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/trace/authorcl1_lmhb_27613.trc (incident=14129):ora-29770: global enqueue process lmon (osid 27573) is hungfor more than 70 secondsincident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/incident/incdir_14129/authorcl1_lmhb_27613_i14129.trctue apr 22 17:26:58 2014sweep [inc][14129]: completedsweep [inc2][14129]: completederror: some process(s) is not making progress.lmhb (ospid: 27613) is terminating the instance.please check lmhb trace filefor more details.please also check the cpu load, i/o loadand other system propertiesfor anomalous behaviorerror: some process(s) is not making progress.tue apr 22 17:26:58 2014system state dump requested by (instance=1, osid=27613 (lmhb)), summary=[abnormal instance termination].lmhb (ospid: 27613): terminating the instance due to error 29770system state dumped to trace file /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/trace/authorcl1_diag_27561.trctue apr 22 17:27:00 2014ora-1092 : opitsk aborting processtue apr 22 17:27:01 2014license high water mark = 144tue apr 22 17:27:08 2014termination issued to instance processes. waitingfor the processes toexitinstance termination failed to kill oneor more processesinstance terminated by lmhb, pid = 27613tue apr 22 17:27:15 2014user (ospid: 1378): terminating the instancetermination issued to instance processes. waitingfor the processes toexittue apr 22 17:27:25 2014instance termination failed to kill oneor more processesinstance terminated by user, pid = 1378tue apr 22 21:51:56 2014adjusting the default value of parameter parallel_max_serversfrom 640 to 135 due to the value of parameter processes (150)starting oracle instance (normal)
我们可以看到，最早在apr 22 17:25:05 2014 时间点,即抛出lmon ipc send timeout的错误了。
receiver: inst 2 binc 95439 ospid 13752 这里的receiver进程为节点2的13752进程，即节点2的lmon进程。
对于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。
其次，lmon进程主要通过2种心跳机制来检查判断集群节点的健康状态：
1) 网络心跳 （主要是通过ping进行检测）
2) 控制文件磁盘心跳，其实就是每个节点的ckpt进程每3s更新一次controlfile的机制。
所以这里大家可以看出，lmon进程是需要操作controlfile的。否则无法判断第2点。
虽然从上面的错误来看，该实例是被lmhb进程给终止掉的，这里我们需要说明一下，lmbh进程的原理。
lmbh进程是oracle 11r2版本引入的一个进程，该进程的作用的监控lmd,lmon,lck,lms等核心进程，防止这些oracle
关键性后台进程spin或不被阻塞。该进程会定时的将监控的信息打印输出在trace文件中，便于我们进行诊断，
这也是11gr2一个亮点。当lmbh进程发现其他核心进程出现异常时，会尝试发起一些kill动作，如何有进程被阻塞的话。
如果一定时间内仍然无法解决，那么将触发保护，将实例强行终止掉，当然，这是为了保证rac节点数据的完整性和一致性。
这里比较郁闷的是，这个diag的dump并没有产没 /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/trace/authorcl1_diag_27561.trc
我们首先来看下node1的lmon进程的信息：
?12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455 *** action name:() 2014-04-22 17:26:56.052*** 2014-04-22 17:26:49.401==============================lmon (ospid: 27573) has not movedfor 105 sec (1398158808.1398158703)kjfmgcr_hbcheckall: lmon (ospid: 27573) has status 6===================================================== lmon (ospid: 27573) heartbeat report==================================================lmon (ospid: 27573) has no heartbeatsfor 105 sec. (threshold 70 sec): not in wait; last wait ended 89 secs ago. -------------等待了89秒: last wait_id 165313538 at'enq: cf - contention'.==============================dumping process lmon (ospid: 27573) states=================================[ system load state ]===cpu total 16 core 16 socket 16load normal: cur 988 highmark 20480 (3.85 80.00)===[ latch state ]===not in latch get===[ session state object ]===----------------------------------------so: 0x52daba340, type: 4, owner: 0x52f5d8330, flag: init/-/-/0x00if: 0x3 c: 0x3proc=0x52f5d8330, name=session, file=ksu.h line:12624 id:, pg=0(session) sid: 1057 ser: 1 trans: 0x0, creator: 0x52f5d8330flags: (0x51) usr/- flags_idl: (0x1) bsy/-/-/-/-/-flags2: (0x409) -/-/incdid: , short-term did:txn branch: 0x0oct: 0, prv: 0, sql: 0x0, psql: 0x0, user: 0/sysksuxds false at location: 0service name: sys$backgroundcurrent wait stack:not in wait; last wait ended 1 min 29 sec agothere are 1 sessions blocked by this session.dumping one waiter:inst: 1, sid: 297, ser: 6347wait event:'name-service call wait'p1:'waittime'=0x32p2:''=0x0p3:''=0x0row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0min_blocked_time: 0 secs, waiter_cache_ver: 30272wait state:fixed_waits=0 flags=0x20 boundary=0x0/-1session wait history:elapsed time of 1 min 29 sec since last wait ---lmon进程等待enq: cf - contention，等待了1分29秒,即89秒0: waitedfor 'enq: cf - contention'name|mode=0x43460006, 0=0x0, operation=0x3wait_id=165313538 seq_num=35946 snap_id=1wait times: snap=1.027254 sec, exc=1.027254 sec, total=1.027254 secwait times: max=1.000000 secwait counts: calls=1 os=1occurred after 0.000109 sec of elapsed time。。。。。。
如下是该进程的资源使用情况：
?123456 *** 2014-04-22 17:26:57.229loadavg : 3.94 3.80 3.99swap info: free_mem = 36949.53m rsv = 24548.22malloc = 23576.62m avail = 45643.61m swap_free = 46615.21mf s uid pid ppid c pri ni addr sz wchan stime tty time cmd0 o oa 27573 1 6 79 20 ? 799187 jan 23 ? 1589:29 ora_lmon_authorcl1
我们可以看到，系统在该时间点load并不高，memory也很充足。
这里有一个问题，该节点lmon进程hung的原因是什么？ 从日志分析来看，是由于无法获得enq: cf – contention。
我们知道ckpt 进程会定时更新操作controlfile,且就需要获得该enqueue。 所有这里我大胆的假设,是由于ckpt持有cf的latch
不释放,导致lmon进程无法获得. 根据这一点我搜mos 发现一个bug，可惜该bug说已经在11.2.0.3中fixed了。
bug 10276173 lmon hang possible while trying to get access to ckpt progress record
该bug描述说，当在进行reconfig时，lmon会尝试去获得ckpt processes record，会等待enq: cf -contention，会导致hung.
根据文档来看，显然这跟我们的实际情况不符。
下面我们来结合node2的日志进行综合分析：
?123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263 tue apr 22 17:25:06 2014ipc send timeout detected. receiver ospid 13752 [oracle@xhdb-server4 (lmon)]tue apr 22 17:26:59 2014dumping diagnostic data in directory=[cdmp_20140422172658], requested by (instance=1, osid=27613 (lmhb)), summary=[abnormal instance termination].tue apr 22 17:29:22 2014warning: aiowait timed out 1 timestue apr 22 17:29:53 2014errors in file /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/trace/authorcl2_dia0_13750.trc (incident=3681):ora-32701: possible hangs up to hang id=3 detectedincident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/incident/incdir_3681/authorcl2_dia0_13750_i3681.trctue apr 22 17:30:24 2014dia0 terminating blocker (ospid: 16818 sid: 578 ser#: 39069) of hang with id = 3requested by master dia0 process on instance 2hang resolution reason: automatic hang resolution was performed to free asignificant number of affected sessions.by terminating session sid: 578 ospid: 16818dia0 successfully terminated session sid:578 ospid:16818 with status 31.dia0 successfully resolved a local, high confidence hang with id=3.tue apr 22 17:30:33 2014lms2 (ospid: 13764) has detected no messaging activity from instance 1lms2 (ospid: 13764) issues an imr to resolve the situationplease check lms2 trace filefor more detail.tue apr 22 17:31:48 2014lmd0 (ospid: 13754) has detected no messaging activity from instance 1lmd0 (ospid: 13754) issues an imr to resolve the situationplease check lmd0 trace filefor more detail.tue apr 22 17:32:03 2014errors in file /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/trace/authorcl2_dia0_13750.trc (incident=3682):ora-32701: possible hangs up to hang id=3 detectedincident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/incident/incdir_3682/authorcl2_dia0_13750_i3682.trctue apr 22 17:32:16 2014ipc send timeout detected. sender: ospid 23666 [oracle@xhdb-server4 (tns v1-v3)]receiver: inst 1 binc 380222 ospid 27575ipc send timeout to 1.0 inc 20for msg type 12 from opid 154ipc send timeout: terminating pid 154 osid 23666tue apr 22 17:32:20 2014ipc send timeout detected. sender: ospid 13746 [oracle@xhdb-server4 (ping)]receiver: inst 1 binc 380164 ospid 27565tue apr 22 17:32:34 2014dia0 terminating blocker (ospid: 16818 sid: 578 ser#: 39069) of hang with id = 3requested by master dia0 process on instance 2hang resolution reason: automatic hang resolution was performed to free asignificant number of affected sessions.by terminating the processdia0 successfully terminated process ospid:16818.dia0 successfully resolved a local, high confidence hang with id=3.tue apr 22 17:32:35 2014lms1 (ospid: 13760) has detected no messaging activity from instance 1lms1 (ospid: 13760) issues an imr to resolve the situationplease check lms1 trace filefor more detail.tue apr 22 17:32:44 2014ipc send timeout detected. sender: ospid 13754 [oracle@xhdb-server4 (lmd0)]receiver: inst 1 binc 380222 ospid 27575ipc send timeout to 1.0 inc 20for msg type 65521 from opid 12tue apr 22 17:33:11 2014lms0 (ospid: 13756) has detected no messaging activity from instance 1lms0 (ospid: 13756) issues an imr to resolve the situationplease check lms0 trace filefor more detail.tue apr 22 17:34:29 2014ipc send timeout detected. sender: ospid 13764 [oracle@xhdb-server4 (lms2)]receiver: inst 1 binc 380309 ospid 27585ipc send timeout to 1.1 inc 20for msg type 65522 from opid 15tue apr 22 17:36:31 2014
我们可以看到node2 在apr 22 17:26:59 2014 节点node1的lmbh终止instance的信息了。然后在后面抛出hung的信息，
不过oracle自动解决了hung的session。 下面我们来看下node2上lmon进程的trace内容：
?12345678910111213141516171819202122232425 *** 2014-04-22 17:26:59.377process diagnostic dumpfor oracle@xhdb-server4 (lmon), os id=13752,pid: 11, proc_ser: 1, sid: 353, sess_ser: 1-------------------------------------------------------------------------------current sql: current wait stack:0: waitingfor 'control file sequential read'file#=0x0, block#=0x23, blocks=0x1wait_id=272969233 seq_num=24337 snap_id=1wait times: snap=7 min 42 sec, exc=7 min 42 sec, total=7 min 42 sec ---已经等待了7分42秒wait times: max=infinite, heur=7 min 42 secwait counts: calls=0 os=0in_wait=1 iflags=0x5a0there are 1 sessions blocked by this session.dumping one waiter:inst: 2, sid: 1092, ser: 49369wait event:'name-service call wait'p1:'waittime'=0x32p2:''=0x0p3:''=0x0row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0min_blocked_time: 0 secs, waiter_cache_ver: 6248wait state:fixed_waits=0 flags=0x22 boundary=0x0/-1session wait history:
从lmon的trace信息我们可以看出，该进程正在等待control file sequential read,且已经等待了7分42秒。
根据trace的时间点，我们可以向前推进7分42秒，换句话讲，从17:19:18秒就开始等待了。
既然是controlfile的等待，那么我们就有必要来看下node2节点上的ckpt进程在干什么了？ 如下是ckpt进程的信息：
?12345678910111213141516171819202122232425262728293031 redo thread mounted by this instance: 2oracle process number: 26unix process pid: 13788, image: oracle@xhdb-server4 (ckpt)*** 2014-04-22 17:26:59.882*** session id:(833.1) 2014-04-22 17:26:59.882*** 2014-04-22 17:26:59.882process diagnostic dumpfor oracle@xhdb-server4 (ckpt), os id=13788,pid: 26, proc_ser: 1, sid: 833, sess_ser: 1-------------------------------------------------------------------------------current sql: current wait stack:0: waitingfor 'control file sequential read'file#=0x0, block#=0x1, blocks=0x1wait_id=14858985 seq_num=48092 snap_id=1wait times: snap=7 min 40 sec, exc=7 min 40 sec, total=7 min 40 sec ----等待了7分40秒wait times: max=infinite, heur=7 min 40 secwait counts: calls=0 os=0in_wait=1 iflags=0x5a0there are 2 sessions blocked by this session.dumping one waiter:inst: 2, sid: 291, ser: 59157wait event:'dfs lock handle'p1:'type|mode'=0x43490005p2:'id1'=0xap3:'id2'=0x2row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0min_blocked_time: 352 secs, waiter_cache_ver: 6248wait state:fixed_waits=0 flags=0x22 boundary=0x0/-1
我们可以看到，node2的ckpt进程等待control file sequential read,等待了7分40秒。同时大家还可以看到，ckpt
进程阻塞了2个进程，也就是说ckpt进程有2个waiter，其中一个waiter的信息是：sid:291,ser:59157
且该waiter进程的等待事件居然是dfs lock handle,这是一个比较危险的event。 这里我们还无法确认这个waiter是什么？
同时ckpt进程为啥等待这么长的时间 ？
大家知道11g引入的hung auto resolution，那么我们就来看下node1上的diag的信息：
?123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354 unix process pid: 27571, image: oracle@xhdb-server3 (dia0)*** 2014-04-22 17:22:01.536*** session id:(961.1) 2014-04-22 17:22:01.536*** client id:() 2014-04-22 17:22:01.536*** service name:(sys$background) 2014-04-22 17:22:01.536*** module name:() 2014-04-22 17:22:01.536*** action name:() 2014-04-22 17:22:01.536one ormore possible hangs have been detected on your system.these could be genuine hangs in which no further progress willbe made without intervention,or it may be very slow progressin the system due to high load.previously detectedand output hangs are not displayed again.instead, the 'victim information' section will indicate thatthe victim is from an'existing hang' under the'previous hang'column.'verified hangs'below indicate one ormore hangs that were foundand identify the final blocking session and instance on whichthey occurred. since the current hang resolution state is'process',any hangs requiring sessionor process termination will beautomatically resolved.any hangs with a 'hang resolution action' of 'unresolvable'will be ignored. these types of hangs will either be resolvedby another layer in the rdbmsor cannot be resolvedas they mayrequire external intervention.deadlocks (also named cycles) are currently not resolved evenifhang resolution is enabled. the'hang type' of dlck in the'verified hangs'output identifies these hangs.below that are the complete hang chains from the time the hangwas detected.the following information will assist oracle support servicesin further analysis of the root cause of the hang.*** 2014-04-22 17:22:01.537verified hangs in the systemroot chain total hanghang hang inst root #hung #hung hang hang resolutionid type status num sess sess sess conf span action----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------2 hang vicseltd 2 833 2 2 high local ignrd:instkillnotahang ignored reason: since instance termination is not allowed, automatichang resolution cannot be performed.inst# sessid ser# ospid prcnm event----- ------ ----- --------- ----- -----2 291 59157 10646 m000 dfs lock handle ----大家注意这里的sid和ser#以及prcnm2 833 1 13788 ckpt control file sequential read
这里提到m000进程，大家应该知道这是跟awr快照有关系的进程，该进程其实是被ckpt所阻塞，我们也可以来看下该进程
的情况，如下：
?123456789101112131415161718192021222324252627282930 *** 2014-04-22 17:27:00.778process diagnostic dumpfor oracle@xhdb-server4 (m000), os id=10646,pid: 57, proc_ser: 143, sid: 291, sess_ser: 59157-------------------------------------------------------------------------------current sql:select tablespace_id, rfno, allocated_space, file_size, file_maxsize, changescn_base, changescn_wrap, flag,inst_id from sys.ts$, gv$filespace_usagewhere ts# = tablespace_id andonline$ != 3 and (changescn_wrap > pitrscnwrpor (changescn_wrap = pitrscnwrp and changescn_base >= pitrscnbas)) and inst_id != :inst and (changescn_wrap > :wor (changescn_wrap = :w and changescn_base >= :b))current wait stack:0: waitingfor 'dfs lock handle'type|mode=0x43490005, id1=0xa, id2=0x2wait_id=6 seq_num=7 snap_id=1wait times: snap=6 min 12 sec, exc=6 min 12 sec, total=6 min 12 secwait times: max=infinite, heur=6 min 12 secwait counts: calls=818 os=818in_wait=1 iflags=0x15a2there is at least one session blocking this session.dumping 2 direct blocker(s):inst: 2, sid: 833, ser: 1inst: 1, sid: 482, ser: 1dumpingfinal blocker:inst: 2, sid: 833, ser: 1 -----最终的blocker是833，也就是node2节点的ckpt进程。there are 1 sessions blocked by this session.dumping one waiter:inst: 1, sid: 581, ser: 36139wait event:'dfs lock handle'p1:'type|mode'=0x43490005p2:'id1'=0xap3:'id2'=0x5
从这里看,root sess却是833,也就是我们node2节点的ckpt进程。 到这里或许有人会说，问题的原因
应该很明确了，由于node2 ckpt的异常，到这node2 节点lmon进程异常，由于需要和node1的lmon进程
进行通信，导致node1 的lmon进程出现ipc send timeout的情况。
其实不然，到最后至始至终我们都没有完全弄清楚为何ckpt进程会等待这么长时间 ？
到这里我不得不怀疑io的问题了，再回过头来分析node1的diag trace时，发现一个有趣的事情：
?123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687 *** 2014-04-22 17:24:08.363verified hangs in the systemroot chain total hanghang hang inst root #hung #hung hang hang resolutionid type status num sess sess sess conf span action----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------7 hang vicseltd 2 801 2 3 high local ignrd:instkillnotahang ignored reason: since instance termination is not allowed, automatichang resolution cannot be performed.inst# sessid ser# ospid prcnm event----- ------ ----- --------- ----- -----2 996 39917 6598 fg log file sync2 801 1 13786 lgwr log file parallel write。。。。。省略部分内容-------------------------------------------------------------------------------chain 2:-------------------------------------------------------------------------------oracle session identified by:{instance: 1 (authorcl.authorcl1)os id: 22323process id: 64, oracle@xhdb-server3session id: 14session serial #: 29257}is waitingfor 'log file sync'with wait info:{p1:'buffer#'=0x2abp2:'sync scn'=0x1ed4d8betime in wait: 4 min 18 sectimeout after: neverwait id: 13287blocking: 0 sessionswait history:* time between current waitand wait #1: 0.000388 sec1. event:'sql*net message from client'time waited: 0.000486 secwait id: 13286 p1:'driver id'=0x54435000p2:'#bytes'=0x1* time between wait #1and #2: 0.000027 sec2. event:'sql*net message to client'time waited: 0.000003 secwait id: 13285 p1:'driver id'=0x54435000p2:'#bytes'=0x1* time between wait #2and #3: 0.001494 sec3. event:'sql*net message from client'time waited: 0.002089 secwait id: 13284 p1:'driver id'=0x54435000p2:'#bytes'=0x1}andis blocked by=> oracle session identified by:{instance: 1 (authorcl.authorcl1)os id: 27634process id: 20, oracle@xhdb-server3 (lgwr)session id: 386session serial #: 1}which is waitingfor 'log file parallel write'with wait info:{p1:'files'=0x1p2:'blocks'=0x2p3:'requests'=0x1time in wait: 4 min 32 sec -----等待了4分32秒timeout after: neverwait id: 51742574blocking: 17 sessions ------阻塞了17个sessionwait history:* time between current waitand wait #1: 0.000176 sec1. event:'rdbms ipc message'time waited: 0.047194 secwait id: 51742573 p1:'timeout'=0x22* time between wait #1and #2: 0.000399 sec2. event:'log file parallel write'time waited: 0.004006 secwait id: 51742572 p1:'files'=0x1p2:'blocks'=0x2p3:'requests'=0x1* time between wait #2and #3: 0.000318 sec3. event:'rdbms ipc message'time waited: 2.654606 secwait id: 51742571 p1:'timeout'=0x12c}chain 2 signature:'log file parallel write''log file sync'
我们可以看到，node1上，lgwr进程阻塞了17个会话，等待log file parallel write，一直持续了4分32秒。
如果将时间点2014-04-22 17:24:08，向前推进4分32秒，那么就是2014-04-22 17:19:36.
我们再来检查node2的操作系统日志你会发现有意思的事情：
?1234567891011 apr 22 17:19:16 xhdb-server4 vxio: [id 442312 kern.notice] notice: vxvm vvr vxio v-5-0-209 log overflow protection on rlink oa_zs_bj triggered dcm protectionapr 22 17:19:16 xhdb-server4 vxio: [id 636438 kern.warning] warning: vxvm vvr vxio v-5-0-1905 replication stoppedfor rvg rvg_oa due to srl overflow, dcm protection is triggered. to start replication, perform dcm resynchronization usingvradmin resync command.apr 22 19:41:19 xhdb-server4 su: [id 810491 auth.crit]'su root' failed for oa on /dev/pts/5apr 22 21:31:38 xhdb-server4 su: [id 810491 auth.crit]'su grid' failed for root on /dev/pts/14apr 22 21:36:03 xhdb-server4 agentframework[5814]: [id 702911 daemon.notice] vcs error v-16-2-13067 thread(4) agent is calling cleanfor resource(cssd_oaora) because the resource became offline unexpectedly, on its own.apr 22 21:36:03 xhdb-server4 had[5704]: [id 702911 daemon.notice] vcs error v-16-2-13067 (xhdb-server4) agent is calling cleanfor resource(cssd_oaora) because the resource became offline unexpectedly, on its own.apr 22 21:36:06 xhdb-server4 agentframework[5814]: [id 702911 daemon.notice] vcs error v-16-2-13068 thread(4) resource(cssd_oaora) - clean completed successfully.apr 22 21:40:51 xhdb-server4 reboot: [id 662345 auth.crit] rebooted by rootapr 22 21:41:14 xhdb-server4 amf: [id 451996 kern.notice] amf notice v-292-1-67 signal receivedwhile waiting for event on reaper 'cfsmount'. returning.apr 22 21:41:14 xhdb-server4 amf: [id 451996 kern.notice] amf notice v-292-1-67 signal receivedwhile waiting for event on reaper 'cfsfsckd'. returning.apr 23 00:31:59 xhdb-server4 genunix: [id 540533 kern.notice] ^msunos release 5.10 version generic_147440-25 64-bit
我们可以看到,在17:19:16秒时vertias的vvr出现了异常。这也就是为什么我们在前面分析看到node2在17:19:18时出现control file sequential read
等待的原因。虽然从vcs的日志什么信息：
?123456 2014/04/22 14:39:12 vcs info v-16-1-53504 vcs engine alive message!!2014/04/22 18:39:13 vcs info v-16-1-53504 vcs engine alive message!!2014/04/22 21:36:03 vcs error v-16-2-13067 (xhdb-server4) agent is calling cleanfor resource(cssd_oaora) because the resource became offline unexpectedly, on its own.2014/04/22 21:36:06 vcs info v-16-2-13068 (xhdb-server4) resource(cssd_oaora) - clean completed successfully.2014/04/22 21:36:09 vcs info v-16-1-10307 resource cssd_oaora (owner: unspecified, group: sg_oaora) is offline on xhdb-server4 (not initiated by vcs)2014/04/22 21:36:09 vcs notice v-16-1-10446 group sg_oaora is offline on system xhdb-server4
所以，最后我的感觉是根本原因是vcs的问题。虽然vertias的工程师一直解释这里的log overflow protection没有太大的关系。
针对这个问题，欢迎大家探讨。
补充：关于ora-29770导致实例crash的问题，oracle确实有不少的bug，但是针对这个情况，目前没有发现符合的。如下是来自oracle mos的搜索结果：
bug 11890804：lmhb crashes instance with ora-29770 after long “control file sequential read” waits
bug 8888434： lmhb crashes the instance with lmon waiting on controlfile read
bug 11890804: lmhb terminate instance when lmon wait change from cf read after 60 sec
bug 13467673: css misscount and all asm down with ora-29770 by lmhb
bug 13390052: kjfmgcr_hbcheckall messages are continuously logged in lmhb trace file.
bug 13322797: lmhb terminates the instance due to error 29770
bug 13061883: lmhb is terminating the instance during shutdown immediate
bug 12886605: essc: lmhb terminate instance due to 29770 – lmon wait enq: am – disk offline
bug 12757321: lmhb terminating the instance due to error 29770
bug 10296263: lmhb (ospid: 15872): terminating the instance due to error 29770
bug 10431752: single node rac: lmhb terminates instance due to 29770
bug 11656856: lmhb (ospid: 27701): terminating the instance due to error 29770
bug 10411143: instance crashes with ipc send timeout and lmhb terminates with ora-29770
bug 11704041: database instance crash by lmhb process
bug 10412545: ora-29770 lmhb terminate instance due to various long css wait
bug 10147827: instance terminated by lmhb with error ora-29770
bug 10016974: ora-29770 lmd is hung for more than 70 seconds and lmhb terminate instance
bug 9376100: lmhb terminating instance due error 29770