11.2.0.3 RAC（VCS）节点crash以及hang的问题分析

昨天某个客户的一套双节RAC其中一个节点crash,同时最后导致另外一个节点也hang住,只能shutdown abort.
且出现shutdown abort实例之后，还有部分进程无法通过kill -9 进行kill的情况。其中有lgwr，arch等进程.

首先我们来看下，在下午出现crash的节点的alert log信息：

Tue Apr 22 17:16:04 2014
Deleted Oracle managed file /oa1/arch/AUTHORCL/archivelog/2014_03_14/o1_mf_2_4878_9l51y1cc_.arc
Deleted Oracle managed file /oa1/arch/AUTHORCL/archivelog/2014_03_14/o1_mf_2_4879_9l529hc6_.arc
Archived Log entry 10847 added for thread 1 sequence 5314 ID 0xffffffffae21a60f dest 1:
Tue Apr 22 17:25:05 2014
IPC Send timeout detected. Sender: ospid 27573 [oracle@xhdb-server3 (LMON)]
Receiver: inst 2 binc 95439 ospid 13752
Communications reconfiguration: instance_number 2
Tue Apr 22 17:26:49 2014
LMON (ospid: 27573) has not called a wait for 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 hung for more than 70 seconds
Incident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/incident/incdir_14129/authorcl1_lmhb_27613_i14129.trc
Tue Apr 22 17:26:58 2014
Sweep [inc][14129]: completed
Sweep [inc2][14129]: completed
ERROR: Some process(s) is not making progress.
LMHB (ospid: 27613) is terminating the instance.
Please check LMHB trace file for more details.
Please also check the CPU load, I/O load and other system properties for anomalous behavior
ERROR: Some process(s) is not making progress.
Tue Apr 22 17:26:58 2014
System state dump requested by (instance=1, osid=27613 (LMHB)), summary=[abnormal instance termination].
LMHB (ospid: 27613): terminating the instance due to error 29770
System State dumped to trace file /u01/app/oa_base/diag/rdbms/authorcl/authorcl1/trace/authorcl1_diag_27561.trc
Tue Apr 22 17:27:00 2014
ORA-1092 : opitsk aborting process
Tue Apr 22 17:27:01 2014
License high water mark = 144
Tue Apr 22 17:27:08 2014
Termination issued to instance processes. Waiting for the processes to exit
Instance termination failed to kill one or more processes
Instance terminated by LMHB, pid = 27613
Tue Apr 22 17:27:15 2014
USER (ospid: 1378): terminating the instance
Termination issued to instance processes. Waiting for the processes to exit
Tue Apr 22 17:27:25 2014
Instance termination failed to kill one or more processes
Instance terminated by USER, pid = 1378
Tue Apr 22 21:51:56 2014
Adjusting the default value of parameter parallel_max_servers
from 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进程的信息：

*** ACTION NAME:() 2014-04-22 17:26:56.052
 
*** 2014-04-22 17:26:49.401
==============================
LMON (ospid: 27573) has not moved for 105 sec (1398158808.1398158703)
kjfmGCR_HBCheckAll: LMON (ospid: 27573) has status 6
==================================================
=== LMON (ospid: 27573) Heartbeat Report
==================================================
LMON (ospid: 27573) has no heartbeats for 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 16
 Load 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/-/-/0x00 if: 0x3 c: 0x3
 proc=0x52f5d8330, name=session, file=ksu.h LINE:12624 ID:, pg=0
 (session) sid: 1057 ser: 1 trans: 0x0, creator: 0x52f5d8330
 flags: (0x51) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
 flags2: (0x409) -/-/INC
 DID: , short-term DID: 
txn branch: 0x0
 oct: 0, prv: 0, sql: 0x0, psql: 0x0, user: 0/SYS
 ksuxds FALSE at location: 0
 service name: SYS$BACKGROUND
 Current Wait Stack:
 Not in wait; last wait ended 1 min 29 sec ago 
There are 1 sessions blocked by this session.
 Dumping one waiter:
 inst: 1, sid: 297, ser: 6347
 wait event: 'name-service call wait'
 p1: 'waittime'=0x32
 p2: ''=0x0
 p3: ''=0x0
 row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
 min_blocked_time: 0 secs, waiter_cache_ver: 30272
 Wait State:
 fixed_waits=0 flags=0x20 boundary=0x0/-1
 Session Wait History:
 elapsed time of 1 min 29 sec since last wait  ---LMON进程等待enq: CF - contention，等待了1分29秒,即89秒
 0: waited for 'enq: CF - contention'
 name|mode=0x43460006, 0=0x0, operation=0x3
 wait_id=165313538 seq_num=35946 snap_id=1
 wait times: snap=1.027254 sec, exc=1.027254 sec, total=1.027254 sec
 wait times: max=1.000000 sec
 wait counts: calls=1 os=1
 occurred after 0.000109 sec of elapsed time
 。。。。。。

如下是该进程的资源使用情况：

*** 2014-04-22 17:26:57.229
loadavg : 3.94 3.80 3.99
swap info: free_mem = 36949.53M rsv = 24548.22M 
alloc = 23576.62M avail = 45643.61M swap_free = 46615.21M
 F S      UID   PID  PPID   C PRI NI     ADDR     SZ    WCHAN    STIME TTY         TIME CMD
 0 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的日志进行综合分析：

Tue Apr 22 17:25:06 2014
IPC Send timeout detected. Receiver ospid 13752 [oracle@xhdb-server4 (LMON)]
Tue Apr 22 17:26:59 2014
Dumping diagnostic data in directory=[cdmp_20140422172658], requested by (instance=1, osid=27613 (LMHB)), summary=[abnormal instance termination].
Tue Apr 22 17:29:22 2014
WARNING: aiowait timed out 1 times
Tue Apr 22 17:29:53 2014
Errors 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 detected
Incident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/incident/incdir_3681/authorcl2_dia0_13750_i3681.trc
Tue Apr 22 17:30:24 2014
DIA0 terminating blocker (ospid: 16818 sid: 578 ser#: 39069) of hang with ID = 3
 requested by master DIA0 process on instance 2
 Hang Resolution Reason: Automatic hang resolution was performed to free a
 significant number of affected sessions.
 by terminating session sid: 578 ospid: 16818
DIA0 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 2014
LMS2 (ospid: 13764) has detected no messaging activity from instance 1
LMS2 (ospid: 13764) issues an IMR to resolve the situation
Please check LMS2 trace file for more detail.
Tue Apr 22 17:31:48 2014
LMD0 (ospid: 13754) has detected no messaging activity from instance 1
LMD0 (ospid: 13754) issues an IMR to resolve the situation
Please check LMD0 trace file for more detail.
Tue Apr 22 17:32:03 2014
Errors 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 detected
Incident details in: /u01/app/oa_base/diag/rdbms/authorcl/authorcl2/incident/incdir_3682/authorcl2_dia0_13750_i3682.trc
Tue Apr 22 17:32:16 2014
IPC Send timeout detected. Sender: ospid 23666 [oracle@xhdb-server4 (TNS V1-V3)]
Receiver: inst 1 binc 380222 ospid 27575
IPC Send timeout to 1.0 inc 20 for msg type 12 from opid 154
IPC Send timeout: Terminating pid 154 osid 23666
Tue Apr 22 17:32:20 2014
IPC Send timeout detected. Sender: ospid 13746 [oracle@xhdb-server4 (PING)]
Receiver: inst 1 binc 380164 ospid 27565
Tue Apr 22 17:32:34 2014
DIA0 terminating blocker (ospid: 16818 sid: 578 ser#: 39069) of hang with ID = 3
 requested by master DIA0 process on instance 2
 Hang Resolution Reason: Automatic hang resolution was performed to free a
 significant number of affected sessions.
 by terminating the process
DIA0 successfully terminated process ospid:16818.
DIA0 successfully resolved a LOCAL, HIGH confidence hang with ID=3.
Tue Apr 22 17:32:35 2014
LMS1 (ospid: 13760) has detected no messaging activity from instance 1
LMS1 (ospid: 13760) issues an IMR to resolve the situation
Please check LMS1 trace file for more detail.
Tue Apr 22 17:32:44 2014
IPC Send timeout detected. Sender: ospid 13754 [oracle@xhdb-server4 (LMD0)]
Receiver: inst 1 binc 380222 ospid 27575
IPC Send timeout to 1.0 inc 20 for msg type 65521 from opid 12
Tue Apr 22 17:33:11 2014
LMS0 (ospid: 13756) has detected no messaging activity from instance 1
LMS0 (ospid: 13756) issues an IMR to resolve the situation
Please check LMS0 trace file for more detail.
Tue Apr 22 17:34:29 2014
IPC Send timeout detected. Sender: ospid 13764 [oracle@xhdb-server4 (LMS2)]
Receiver: inst 1 binc 380309 ospid 27585
IPC Send timeout to 1.1 inc 20 for msg type 65522 from opid 15
Tue Apr 22 17:36:31 2014

我们可以看到Node2 在Apr 22 17:26:59 2014 节点Node1的LMBH终止instance的信息了。然后在后面抛出hung的信息，
不过Oracle自动解决了hung的session。 下面我们来看下Node2上lmon进程的trace内容：

*** 2014-04-22 17:26:59.377
Process diagnostic dump for oracle@xhdb-server4 (LMON), OS id=13752,
pid: 11, proc_ser: 1, sid: 353, sess_ser: 1 
-------------------------------------------------------------------------------
current sql: <none>
Current Wait Stack:
 0: waiting for 'control file sequential read'
 file#=0x0, block#=0x23, blocks=0x1
 wait_id=272969233 seq_num=24337 snap_id=1
 wait 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 sec
 wait counts: calls=0 os=0
 in_wait=1 iflags=0x5a0
There are 1 sessions blocked by this session.
Dumping one waiter:
 inst: 2, sid: 1092, ser: 49369
 wait event: 'name-service call wait'
 p1: 'waittime'=0x32
 p2: ''=0x0
 p3: ''=0x0
 row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
 min_blocked_time: 0 secs, waiter_cache_ver: 6248
Wait State:
 fixed_waits=0 flags=0x22 boundary=0x0/-1
Session Wait History:

从lmon的trace信息我们可以看出，该进程正在等待control file sequential read,且已经等待了7分42秒。

根据trace的时间点，我们可以向前推进7分42秒，换句话讲，从17:19:18秒就开始等待了。

既然是controlfile的等待，那么我们就有必要来看下Node2节点上的ckpt进程在干什么了？ 如下是ckpt进程的信息：

Redo thread mounted by this instance: 2
Oracle process number: 26
Unix 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.882
Process diagnostic dump for oracle@xhdb-server4 (CKPT), OS id=13788,
pid: 26, proc_ser: 1, sid: 833, sess_ser: 1 
-------------------------------------------------------------------------------
current sql: <none>
Current Wait Stack:
 0: waiting for 'control file sequential read'
 file#=0x0, block#=0x1, blocks=0x1
 wait_id=14858985 seq_num=48092 snap_id=1
 wait 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 sec
 wait counts: calls=0 os=0
 in_wait=1 iflags=0x5a0
There are 2 sessions blocked by this session.
Dumping one waiter:
 inst: 2, sid: 291, ser: 59157
 wait event: 'DFS lock handle'
 p1: 'type|mode'=0x43490005
 p2: 'id1'=0xa
 p3: 'id2'=0x2
 row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
 min_blocked_time: 352 secs, waiter_cache_ver: 6248
Wait 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的信息：

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.536
 

One or more possible hangs have been detected on your system.
These could be genuine hangs in which no further progress will
be made without intervention, or it may be very slow progress
in the system due to high load.
 
Previously detected and output hangs are not displayed again.
Instead, the 'Victim Information' section will indicate that
the victim is from an 'Existing Hang' under the 'Previous Hang'
column.
 
'Verified Hangs' below indicate one or more hangs that were found
and identify the final blocking session and instance on which
they occurred. Since the current hang resolution state is 'PROCESS',
any hangs requiring session or process termination will be
automatically resolved.
 
Any hangs with a 'Hang Resolution Action' of 'Unresolvable'
will be ignored. These types of hangs will either be resolved
by another layer in the RDBMS or cannot be resolved as they may
require external intervention.
 
Deadlocks (also named cycles) are currently NOT resolved even if
hang 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 hang
was detected.
 
The following information will assist Oracle Support Services
in further analysis of the root cause of the hang.

*** 2014-04-22 17:22:01.537
Verified Hangs in the System
 Root       Chain Total               Hang               
Hang Hang          Inst Root  #hung #hung  Hang   Hang  Resolution         
ID Type Status   Num  Sess   Sess  Sess  Conf   Span  Action             
----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
 2 HANG VICSELTD    2   833     2     2   HIGH  LOCAL IGNRD:InstKillNotA 
Hang Ignored Reason: Since instance termination is not allowed, automatic
 hang resolution cannot be performed.
 
inst# SessId  Ser#     OSPID PrcNm Event
 ----- ------ ----- --------- ----- -----
 2    291 59157     10646  M000 DFS lock handle                   ----大家注意这里的sid和ser#以及PrcNm
 2    833     1     13788  CKPT control file sequential read

这里提到M000进程，大家应该知道这是跟AWR快照有关系的进程，该进程其实是被CKPT所阻塞，我们也可以来看下该进程
的情况，如下：

*** 2014-04-22 17:27:00.778
Process diagnostic dump for 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_USAGE where ts# = tablespace_id and online$ != 3 and (changescn_wrap > PITRSCNWRP 
or     (changescn_wrap = PITRSCNWRP and changescn_base >= PITRSCNBAS)) and inst_id != :inst and (changescn_wrap > :w 
or (changescn_wrap = :w and changescn_base >= :b))
Current Wait Stack:
 0: waiting for 'DFS lock handle'
 type|mode=0x43490005, id1=0xa, id2=0x2
 wait_id=6 seq_num=7 snap_id=1
 wait times: snap=6 min 12 sec, exc=6 min 12 sec, total=6 min 12 sec
 wait times: max=infinite, heur=6 min 12 sec
 wait counts: calls=818 os=818
 in_wait=1 iflags=0x15a2
There is at least one session blocking this session.
 Dumping 2 direct blocker(s):
 inst: 2, sid: 833, ser: 1
 inst: 1, sid: 482, ser: 1
 Dumping final 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: 36139
 wait event: 'DFS lock handle'
 p1: 'type|mode'=0x43490005
 p2: 'id1'=0xa
 p3: 'id2'=0x5

从这里看,root sess却是833,也就是我们Node2节点的CKPT进程。 到这里或许有人会说，问题的原因
应该很明确了，由于Node2 ckpt的异常，到这Node2 节点Lmon进程异常，由于需要和Node1的Lmon进程
进行通信，导致Node1 的lmon进程出现IPc send timeout的情况。

其实不然，到最后至始至终我们都没有完全弄清楚为何CKPT进程会等待这么长时间 ？

到这里我不得不怀疑IO的问题了，再回过头来分析Node1的diag trace时，发现一个有趣的事情：

*** 2014-04-22 17:24:08.363
Verified Hangs in the System
 Root       Chain Total               Hang               
Hang Hang          Inst Root  #hung #hung  Hang   Hang  Resolution         
ID Type Status   Num  Sess   Sess  Sess  Conf   Span  Action             
----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
 7 HANG VICSELTD    2   801     2     3   HIGH  LOCAL IGNRD:InstKillNotA 
Hang Ignored Reason: Since instance termination is not allowed, automatic
 hang resolution cannot be performed.
 
inst# SessId  Ser#     OSPID PrcNm Event
 ----- ------ ----- --------- ----- -----
 2    996 39917      6598    FG log file sync
 2    801     1     13786  LGWR log file parallel write
。。。。。省略部分内容
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
 Oracle session identified by:
 {
 instance: 1 (authorcl.authorcl1)
 os id: 22323
 process id: 64, oracle@xhdb-server3
 session id: 14
 session serial #: 29257
 }
 is waiting for 'log file sync' with wait info:
 {
 p1: 'buffer#'=0x2ab
 p2: 'sync scn'=0x1ed4d8be
 time in wait: 4 min 18 sec
 timeout after: never
 wait id: 13287
 blocking: 0 sessions
 wait history:
 * time between current wait and wait #1: 0.000388 sec
 1.       event: 'SQL*Net message from client'
 time waited: 0.000486 sec
 wait id: 13286           p1: 'driver id'=0x54435000
 p2: '#bytes'=0x1
 * time between wait #1 and #2: 0.000027 sec
 2.       event: 'SQL*Net message to client'
 time waited: 0.000003 sec
 wait id: 13285           p1: 'driver id'=0x54435000
 p2: '#bytes'=0x1
 * time between wait #2 and #3: 0.001494 sec
 3.       event: 'SQL*Net message from client'
 time waited: 0.002089 sec
 wait id: 13284           p1: 'driver id'=0x54435000
 p2: '#bytes'=0x1
 }
 and is blocked by
 => Oracle session identified by:
 {
 instance: 1 (authorcl.authorcl1)
 os id: 27634
 process id: 20, oracle@xhdb-server3 (LGWR)
 session id: 386
 session serial #: 1
 }
 which is waiting for 'log file parallel write' with wait info:
 {
 p1: 'files'=0x1
 p2: 'blocks'=0x2
 p3: 'requests'=0x1
 time in wait: 4 min 32 sec            -----等待了4分32秒
 timeout after: never
 wait id: 51742574
 blocking: 17 sessions            ------阻塞了17个Session
 wait history:
 * time between current wait and wait #1: 0.000176 sec
 1.       event: 'rdbms ipc message'
 time waited: 0.047194 sec
 wait id: 51742573        p1: 'timeout'=0x22
 * time between wait #1 and #2: 0.000399 sec
 2.       event: 'log file parallel write'
 time waited: 0.004006 sec
 wait id: 51742572        p1: 'files'=0x1
 p2: 'blocks'=0x2
 p3: 'requests'=0x1
 * time between wait #2 and #3: 0.000318 sec
 3.       event: 'rdbms ipc message'
 time waited: 2.654606 sec
 wait 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的操作系统日志你会发现有意思的事情：

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 protection
Apr 22 17:19:16 xhdb-server4 vxio: [ID 636438 kern.warning] WARNING: VxVM VVR vxio V-5-0-1905 Replication stopped for RVG rvg_oa due to SRL overflow, DCM protection is triggered. To start replication, perform DCM resynchronization using "vradmin resync" command.
Apr 22 19:41:19 xhdb-server4 su: [ID 810491 auth.crit] 'su root' failed for oa on /dev/pts/5
Apr 22 21:31:38 xhdb-server4 su: [ID 810491 auth.crit] 'su grid' failed for root on /dev/pts/14
Apr 22 21:36:03 xhdb-server4 AgentFramework[5814]: [ID 702911 daemon.notice] VCS ERROR V-16-2-13067 Thread(4) Agent is calling clean for 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 clean for 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 root
Apr 22 21:41:14 xhdb-server4 amf: [ID 451996 kern.notice] AMF NOTICE V-292-1-67 Signal received while 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 received while 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的日志什么信息：

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 clean for 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