再议RAC Brain Split脑裂

这2天在面试DBA Candidate的时候,我问到Oracle RAC中Brain Split脑裂决议的一些概念, 几乎所有的Candidate都告诉我当”只有2个节点的时候,投票算法就失效了,会让2个节点去抢占Quorum Disk,最先获得的节点将活下来” 。 我们姑且把这套理论叫做” 抢占论”。

“抢占论”的具体观点可能与下面这一段文字大同小异:

 

“在集群中,节点间通过某种机制(心跳)了解彼此的健康状态,以确保各节点协调工作。 假设只有”心跳”出现问题, 各个节点还在正常运行, 这时,每个节点都认为其他的节点宕机了, 自己是整个集群环境中的”唯一建在者”,自己应该获得整个集群的”控制权”。 在集群环境中,存储设备都是共享的, 这就意味着数据灾难, 这种情况就是”脑裂”
解决这个问题的通常办法是使用投票算法(Quorum Algorithm). 它的算法机理如下:

观点1:

集群中各个节点需要心跳机制来通报彼此的”健康状态”,假设每收到一个节点的”通报”代表一票。对于三个节点的集群,正常运行时,每个节点都会有3票。 当结点A心跳出现故障但节点A还在运行,这时整个集群就会分裂成2个小的partition。 节点A是一个,剩下的2个是一个。 这是必须剔除一个partition才能保障集群的健康运行。 对于有3个节点的集群, A 心跳出现问题后, B 和 C 是一个partion,有2票, A只有1票。 按照投票算法, B 和C 组成的集群获得控制权, A 被剔除。

 

 

观点2:

如果只有2个节点,投票算法就失效了。 因为每个节点上都只有1票。 这时就需要引入第三个设备:Quorum Device. Quorum Device 通常采用饿是共享磁盘,这个磁盘也叫作Quorum disk。 这个Quorum Disk 也代表一票。 当2个结点的心跳出现问题时, 2个节点同时去争取Quorum Disk 这一票, 最早到达的请求被最先满足。 故最先获得Quorum Disk的节点就获得2票。另一个节点就会被剔除。

 

 

以上这段文字描述中观点1 与我在<Oracle RAC Brain Split Resolution> 一文中提出的看法其实是类似的。  这里再列出我的描述:

在脑裂检查阶段Reconfig Manager会找出那些没有Network Heartbeat而有Disk Heartbeat的节点,并通过Network Heartbeat(如果可能的话)和Disk Heartbeat的信息来计算所有竞争子集群(subcluster)内的节点数目,并依据以下2种因素决定哪个子集群应当存活下去:

  1. 拥有最多节点数目的子集群(Sub-cluster with largest number of Nodes)
  2. 若子集群内数目相等则为拥有最低节点号的子集群(Sub-cluster with lowest node number),举例来说在一个2节点的RAC环境中总是1号节点会获胜。

补充:关于 我引入的子集群的概念的介绍:

“在解决脑裂的场景中,NM还会监控voting disk以了解其他的竞争子集群(subclusters)。关于子集群我们有必要介绍一下,试想我们的环境中存在大量的节点,以Oracle官方构建过的128个节点的环境为我们的想象空间,当网络故障发生时存在多种的可能性,一种可能性是全局的网络失败,即128个节点中每个节点都不能互相发生网络心跳,此时会产生多达128个的信息”孤岛”子集群。另一种可能性是局部的网络失败,128个节点中被分成多个部分,每个部分中包含多于一个的节点,这些部分就可以被称作子集群(subclusters)。当出现网络故障时子集群内部的多个节点仍能互相通信传输投票信息(vote mesg),但子集群或者孤岛节点之间已经无法通过常规的Interconnect网络交流了,这个时候NM Reconfiguration就需要用到voting disk投票磁盘。”

 

争议主要体现在 , “抢占论” 认为当 只有2个节点时 是通过抢占votedisk 的结果来决定具体哪个节点存活下来同时” 抢占论”没有介绍 当存在多个相同节点数目的子集群情况下的结论(譬如4节点的RAC , 1、2节点组成一个子集群,3、4节点组成一个子集群), 若按照2节点时的做法那么依然是通过子集群间抢占votedisk来决定。

 

我个人认为这种说法(“抢占论”)是错误的,不管是具体脑裂时的CRS关键进程css的日志,还是Oracle官方的内部文档都可以说明该问题。

 

我们来看10.2 RAC中的一个场景,假设集群中共有3个节点,其中1号实例没有被启动,集群中只有2个活动节点(active node),发生2号节点的网络失败的故障,因2号节点的member number较小故其通过voting disk向3号节点发起驱逐,具体日志如下:

观察红色部分的日志 ,明确显示了NM(Node Monitor)节点监控服务检查votedisk信息,并计算出了smaller cluster size

以下为2号节点的ocssd.log日志

[    CSSD]2011-04-23 17:42:32.022 [3032460176] >
TRACE: clssnmCheckDskInfo: node 3, vrh3, state 5 with leader 3
has smaller cluster size 1; my cluster size 1 with leader 2

检查voting disk后发现子集群3为最小"子集群"(3号节点的node number较2号大);2号节点为最大子集群

[    CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE:   clssnmEvict: Start
[    CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE:   clssnmEvict:
Evicting node 3, vrh3, birth 3, death 13, impendingrcfg 1, stateflags 0x40d
[    CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE:
clssnmSendShutdown: req to node 3, kill time 1643084

发起对3号节点的驱逐和shutdown request

以下为3号节点的ocssd.log日志:
[    CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR:   clssnmCheckDskInfo:
Aborting local node to avoid splitbrain.
[    CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR:                     :
my node(3), Leader(3), Size(1) VS Node(2), Leader(2), Size(1)

读取voting disk后发现kill block,为避免split brain,自我aborting!

 

 

此外Metalink 上一些官方Note 也明确说明了我以上的观点 , 摘录部分内容如下:

 

1.
When interconnect breaks – keeps the largest cluster possible up, other nodes will be evicted, in 2 node cluster lowest number node remains.
 

2.
Node eviction: pick a cluster node as victim to reboot.Always keep the largest cluster possible up, evicted other nodes two nodes: keep the lowest number node up and evict other

 

实际上有部分Vendor Unix Clusterware集群软件的脑裂可能如确实是以谁先获得 “Quorum disk”为决定因素, 但是自10g 推出的Oracle 自己的Real Application Cluster(RAC) 的clusterware 或者说 CRS( cluster ready services) 在Brain Split Resolution时并非如此,在这方面类推并不能帮助我们找出正确的结论。

 

 


Posted

in

by

Tags:

Comments

13 responses to “再议RAC Brain Split脑裂”

  1. 张明 Avatar
    张明

    看了作者的分析,并结合我这两天在一个客户那遇到的情况。我认为” 抢占论”是实际存在的。客户环境是2节点的RAC,其中一个节点的Network Heartbeat失效,经过测试发现NODE1,NODE2无论那个节点先启动,则另一个节点启动时就会重启。所以作者提到的member number较小的会驱逐较大的说法,这里没有得到验证。

    1. Maclean Liu Avatar

      为什么说抢占论是 错误的?

      1. 抢占论没有 理论依据 没有任何一个官方文档介绍了 抢占论 ,而又有大量 内部文档明确写了”Sub-cluster with lowest node number”

      2. 抢占论 没有 实验依据 , 若我在文章中列出的 场景的 cssd.log 信息明确说明了 在比较subcluster size 的算法

      你所说的 测试表现 并不能说明问题, 另一方面 你的测试结果本身 也不支持 ” 抢占论” ,如果你希望用你的测试来解释该问题 , 请将 2个节点 上Brain split 时 clssnmCheckDskInfo 相关的信息罗列出来

  2. 张明 Avatar
    张明

    [ CSSD]2011-10-30 01:15:33.879 >USER: Oracle Database 10g CSS Release 10.2.0.3.0 Production Copyright 1996, 2004 Oracle. All rights reserved.
    [ CSSD]2011-10-30 01:15:33.879 >USER: CSS daemon log for node hdmis2, number 2, in cluster crs
    [ CSSD]2011-10-30 01:15:33.885 [1] >TRACE: clssscmain: local-only set to false
    [ CSSD]2011-10-30 01:15:33.893 [1] >TRACE: clssnmReadNodeInfo: added node 1 (hdmis1) to cluster
    [ clsdmt]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=hdmis2DBG_CSSD))
    [ CSSD]2011-10-30 01:15:33.899 [1] >TRACE: clssnmReadNodeInfo: added node 2 (hdmis2) to cluster
    [ CSSD]2011-10-30 01:15:33.904 [1029] >TRACE: clssnm_skgxnmon: skgxn init failed
    [ CSSD]2011-10-30 01:15:33.904 [1] >TRACE: clssnm_skgxnonline: Using vacuous skgxn monitor
    [ CSSD]2011-10-30 01:15:33.906 [1] >TRACE: clssnmNMInitialize: misscount set to (30), impending reconfig threshold set to (26000)
    [ CSSD]2011-10-30 01:15:33.907 [1] >TRACE: clssnmNMInitialize: diskShortTimeout set to (27000)ms
    [ CSSD]2011-10-30 01:15:33.908 [1] >TRACE: clssnmNMInitialize: diskLongTimeout set to (200000)ms
    [ CSSD]2011-10-30 01:15:33.912 [1] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (0//dev/rhdisk12)
    [ CSSD]2011-10-30 01:15:33.912 [1030] >TRACE: clssnmvDPT: spawned for disk 0 (/dev/rhdisk12)
    [ CSSD]2011-10-30 01:15:33.914 [1] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (1//dev/rhdisk13)
    [ CSSD]2011-10-30 01:15:33.914 [1287] >TRACE: clssnmvDPT: spawned for disk 1 (/dev/rhdisk13)
    [ CSSD]2011-10-30 01:15:33.916 [1] >TRACE: clssnmDiskStateChange: state from 1 to 2 disk (2//dev/rhdisk14)
    [ CSSD]2011-10-30 01:15:33.916 [1544] >TRACE: clssnmvDPT: spawned for disk 2 (/dev/rhdisk14)
    [ CSSD]2011-10-30 01:15:35.932 [1544] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (2//dev/rhdisk14)
    [ CSSD]2011-10-30 01:15:35.935 [1287] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (1//dev/rhdisk13)
    [ CSSD]2011-10-30 01:15:35.935 [1801] >TRACE: clssnmvKillBlockThread: spawned for disk 2 (/dev/rhdisk14) initial sleep interval (1000)ms
    [ CSSD]2011-10-30 01:15:35.935 [1030] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (0//dev/rhdisk12)
    [ CSSD]2011-10-30 01:15:35.935 [2058] >TRACE: clssnmvKillBlockThread: spawned for disk 1 (/dev/rhdisk13) initial sleep interval (1000)ms
    [ CSSD]2011-10-30 01:15:35.935 [2315] >TRACE: clssnmvKillBlockThread: spawned for disk 0 (/dev/rhdisk12) initial sleep interval (1000)ms
    [ CSSD]2011-10-30 01:15:35.935 [1] >TRACE: clssnmFatalInit: fatal mode enabled
    [ CSSD]2011-10-30 01:15:35.943 [2829] >TRACE: clssnmconnect: connecting to node 2, flags 0x0001, connector 1
    [ CSSD]2011-10-30 01:15:35.952 [2829] >TRACE: clssnmClusterListener: Listening on (ADDRESS=(PROTOCOL=tcp)(HOST=hdmis2_priv)(PORT=49895))

    [ CSSD]2011-10-30 01:15:35.952 [2829] >TRACE: clssnmconnect: connecting to node 0, flags 0x0000, connector 1
    [ CSSD]2011-10-30 01:15:35.952 [2829] >TRACE: clssnmconnect: connecting to node 1, flags 0x0001, connector 0
    [ CSSD]2011-10-30 01:15:35.994 [3086] >TRACE: clssgmclientlsnr: listening on (ADDRESS=(PROTOCOL=ipc)(KEY=Oracle_CSS_LclLstnr_crs_2))
    [ CSSD]2011-10-30 01:15:35.994 [3086] >TRACE: clssgmclientlsnr: listening on (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_hdmis2_crs))
    [ CSSD]2011-10-30 01:15:36.003 [3857] >TRACE: clssgmPeerListener: Listening on (ADDRESS=(PROTOCOL=tcp)(DEV=25)(HOST=10.1.1.2)(PORT=32902))
    [ CSSD]2011-10-30 01:15:35.935 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(10) LATS(4148068) Disk lastSeqNo(10)
    [ CSSD]2011-10-30 01:15:36.135 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(10) LATS(4148268) Disk lastSeqNo(10)
    [ CSSD]2011-10-30 01:15:36.136 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(10) LATS(4148268) Disk lastSeqNo(10)
    [ CSSD]2011-10-30 01:15:37.138 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(11) LATS(4149271) Disk lastSeqNo(11)
    [ CSSD]2011-10-30 01:15:37.139 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(11) LATS(4149271) Disk lastSeqNo(11)
    [ CSSD]2011-10-30 01:15:37.139 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(11) LATS(4149271) Disk lastSeqNo(11)
    [ CSSD]2011-10-30 01:15:38.145 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(12) LATS(4150278) Disk lastSeqNo(12)
    [ CSSD]2011-10-30 01:15:38.149 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(12) LATS(4150281) Disk lastSeqNo(12)
    [ CSSD]2011-10-30 01:15:38.149 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(12) LATS(4150281) Disk lastSeqNo(12)
    [ CSSD]2011-10-30 01:15:39.148 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(13) LATS(4151281) Disk lastSeqNo(13)
    [ CSSD]2011-10-30 01:15:39.159 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(13) LATS(4151291) Disk lastSeqNo(13)
    [ CSSD]2011-10-30 01:15:39.159 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(13) LATS(4151291) Disk lastSeqNo(13)
    [ CSSD]2011-10-30 01:15:40.156 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(14) LATS(4152288) Disk lastSeqNo(14)
    [ CSSD]2011-10-30 01:15:40.160 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(14) LATS(4152292) Disk lastSeqNo(14)
    [ CSSD]2011-10-30 01:15:40.169 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(14) LATS(4152301) Disk lastSeqNo(14)
    [ CSSD]2011-10-30 01:15:41.158 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(15) LATS(4153291) Disk lastSeqNo(15)
    [ CSSD]2011-10-30 01:15:41.160 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(15) LATS(4153292) Disk lastSeqNo(15)
    [ CSSD]2011-10-30 01:15:41.179 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(15) LATS(4153311) Disk lastSeqNo(15)
    [ CSSD]2011-10-30 01:15:42.160 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(16) LATS(4154293) Disk lastSeqNo(16)
    [ CSSD]2011-10-30 01:15:42.166 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(16) LATS(4154299) Disk lastSeqNo(16)
    [ CSSD]2011-10-30 01:15:42.189 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(16) LATS(4154321) Disk lastSeqNo(16)
    [ CSSD]2011-10-30 01:15:43.161 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(17) LATS(4155293) Disk lastSeqNo(17)
    [ CSSD]2011-10-30 01:15:43.177 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(17) LATS(4155309) Disk lastSeqNo(17)
    [ CSSD]2011-10-30 01:15:43.199 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(17) LATS(4155331) Disk lastSeqNo(17)
    [ CSSD]2011-10-30 01:15:44.161 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(18) LATS(4156294) Disk lastSeqNo(18)
    [ CSSD]2011-10-30 01:15:44.178 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(18) LATS(4156311) Disk lastSeqNo(18)
    [ CSSD]2011-10-30 01:15:44.209 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(18) LATS(4156341) Disk lastSeqNo(18)
    [ CSSD]2011-10-30 01:15:45.162 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(19) LATS(4157294) Disk lastSeqNo(19)
    [ CSSD]2011-10-30 01:15:45.187 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(19) LATS(4157319) Disk lastSeqNo(19)
    [ CSSD]2011-10-30 01:15:45.219 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(19) LATS(4157351) Disk lastSeqNo(19)
    [ CSSD]2011-10-30 01:15:46.162 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(20) LATS(4158294) Disk lastSeqNo(20)
    [ CSSD]2011-10-30 01:15:46.196 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(20) LATS(4158328) Disk lastSeqNo(20)
    [ CSSD]2011-10-30 01:15:46.229 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(20) LATS(4158361) Disk lastSeqNo(20)
    [ CSSD]2011-10-30 01:15:47.162 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(21) LATS(4159295) Disk lastSeqNo(21)
    [ CSSD]2011-10-30 01:15:47.265 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(21) LATS(4159397) Disk lastSeqNo(21)
    [ CSSD]2011-10-30 01:15:47.267 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(21) LATS(4159399) Disk lastSeqNo(21)
    [ CSSD]2011-10-30 01:15:48.163 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(22) LATS(4160295) Disk lastSeqNo(22)
    [ CSSD]2011-10-30 01:15:48.268 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(22) LATS(4160400) Disk lastSeqNo(22)
    [ CSSD]2011-10-30 01:15:48.269 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(22) LATS(4160401) Disk lastSeqNo(22)
    [ CSSD]2011-10-30 01:15:49.163 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(23) LATS(4161296) Disk lastSeqNo(23)
    [ CSSD]2011-10-30 01:15:49.278 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(23) LATS(4161410) Disk lastSeqNo(23)
    [ CSSD]2011-10-30 01:15:49.279 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(23) LATS(4161411) Disk lastSeqNo(23)
    [ CSSD]2011-10-30 01:15:50.164 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(24) LATS(4162296) Disk lastSeqNo(24)
    [ CSSD]2011-10-30 01:15:50.288 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(24) LATS(4162420) Disk lastSeqNo(24)
    [ CSSD]2011-10-30 01:15:50.289 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(24) LATS(4162421) Disk lastSeqNo(24)
    [ CSSD]2011-10-30 01:15:51.164 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(25) LATS(4163297) Disk lastSeqNo(25)
    [ CSSD]2011-10-30 01:15:51.289 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(25) LATS(4163422) Disk lastSeqNo(25)
    [ CSSD]2011-10-30 01:15:51.296 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(25) LATS(4163428) Disk lastSeqNo(25)
    [ CSSD]2011-10-30 01:15:52.165 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(26) LATS(4164297) Disk lastSeqNo(26)
    [ CSSD]2011-10-30 01:15:52.290 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(26) LATS(4164422) Disk lastSeqNo(26)
    [ CSSD]2011-10-30 01:15:52.296 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(26) LATS(4164429) Disk lastSeqNo(26)
    [ CSSD]2011-10-30 01:15:53.165 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(27) LATS(4165297) Disk lastSeqNo(27)
    [ CSSD]2011-10-30 01:15:53.290 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(27) LATS(4165422) Disk lastSeqNo(27)
    [ CSSD]2011-10-30 01:15:53.297 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(27) LATS(4165429) Disk lastSeqNo(27)
    [ CSSD]2011-10-30 01:15:54.165 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(28) LATS(4166298) Disk lastSeqNo(28)
    [ CSSD]2011-10-30 01:15:54.290 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(28) LATS(4166423) Disk lastSeqNo(28)
    [ CSSD]2011-10-30 01:15:54.297 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(28) LATS(4166430) Disk lastSeqNo(28)
    [ CSSD]2011-10-30 01:15:55.166 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(29) LATS(4167298) Disk lastSeqNo(29)
    [ CSSD]2011-10-30 01:15:55.291 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(29) LATS(4167423) Disk lastSeqNo(29)
    [ CSSD]2011-10-30 01:15:55.298 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(29) LATS(4167430) Disk lastSeqNo(29)
    [ CSSD]2011-10-30 01:15:56.166 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(30) LATS(4168299) Disk lastSeqNo(30)
    [ CSSD]2011-10-30 01:15:56.291 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(30) LATS(4168424) Disk lastSeqNo(30)
    [ CSSD]2011-10-30 01:15:56.298 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(30) LATS(4168431) Disk lastSeqNo(30)
    [ CSSD]2011-10-30 01:15:57.167 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(31) LATS(4169299) Disk lastSeqNo(31)
    [ CSSD]2011-10-30 01:15:57.292 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(31) LATS(4169424) Disk lastSeqNo(31)
    [ CSSD]2011-10-30 01:15:57.299 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(31) LATS(4169431) Disk lastSeqNo(31)
    [ CSSD]2011-10-30 01:15:58.167 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(32) LATS(4170299) Disk lastSeqNo(32)
    [ CSSD]2011-10-30 01:15:58.292 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(32) LATS(4170424) Disk lastSeqNo(32)
    [ CSSD]2011-10-30 01:15:58.299 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(32) LATS(4170431) Disk lastSeqNo(32)
    [ CSSD]2011-10-30 01:15:59.168 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(33) LATS(4171300) Disk lastSeqNo(33)
    [ CSSD]2011-10-30 01:15:59.292 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(33) LATS(4171425) Disk lastSeqNo(33)
    [ CSSD]2011-10-30 01:15:59.299 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(33) LATS(4171432) Disk lastSeqNo(33)
    [ CSSD]2011-10-30 01:16:00.168 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(34) LATS(4172300) Disk lastSeqNo(34)
    [ CSSD]2011-10-30 01:16:00.293 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(34) LATS(4172425) Disk lastSeqNo(34)
    [ CSSD]2011-10-30 01:16:00.300 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(34) LATS(4172432) Disk lastSeqNo(34)
    [ CSSD]2011-10-30 01:16:01.168 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(35) LATS(4173301) Disk lastSeqNo(35)
    [ CSSD]2011-10-30 01:16:01.293 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(35) LATS(4173426) Disk lastSeqNo(35)
    [ CSSD]2011-10-30 01:16:01.300 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(35) LATS(4173433) Disk lastSeqNo(35)
    [ CSSD]2011-10-30 01:16:02.169 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(36) LATS(4174301) Disk lastSeqNo(36)
    [ CSSD]2011-10-30 01:16:02.294 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(36) LATS(4174426) Disk lastSeqNo(36)
    [ CSSD]2011-10-30 01:16:02.301 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(36) LATS(4174433) Disk lastSeqNo(36)
    [ CSSD]2011-10-30 01:16:03.169 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(37) LATS(4175302) Disk lastSeqNo(37)
    [ CSSD]2011-10-30 01:16:03.294 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(37) LATS(4175426) Disk lastSeqNo(37)
    [ CSSD]2011-10-30 01:16:03.301 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(37) LATS(4175434) Disk lastSeqNo(37)
    [ CSSD]2011-10-30 01:16:04.170 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(38) LATS(4176302) Disk lastSeqNo(38)
    [ CSSD]2011-10-30 01:16:04.295 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(38) LATS(4176427) Disk lastSeqNo(38)
    [ CSSD]2011-10-30 01:16:04.302 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(38) LATS(4176434) Disk lastSeqNo(38)
    [ CSSD]2011-10-30 01:16:05.170 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(39) LATS(4177302) Disk lastSeqNo(39)
    [ CSSD]2011-10-30 01:16:05.295 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(39) LATS(4177427) Disk lastSeqNo(39)
    [ CSSD]2011-10-30 01:16:05.302 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(39) LATS(4177434) Disk lastSeqNo(39)
    [ CSSD]2011-10-30 01:16:06.171 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(40) LATS(4178303) Disk lastSeqNo(40)
    [ CSSD]2011-10-30 01:16:06.295 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(40) LATS(4178428) Disk lastSeqNo(40)
    [ CSSD]2011-10-30 01:16:06.303 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(40) LATS(4178435) Disk lastSeqNo(40)
    [ CSSD]2011-10-30 01:16:07.171 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(41) LATS(4179303) Disk lastSeqNo(41)
    [ CSSD]2011-10-30 01:16:07.296 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(41) LATS(4179428) Disk lastSeqNo(41)
    [ CSSD]2011-10-30 01:16:07.303 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(41) LATS(4179435) Disk lastSeqNo(41)
    [ CSSD]2011-10-30 01:16:08.171 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(42) LATS(4180304) Disk lastSeqNo(42)
    [ CSSD]2011-10-30 01:16:08.296 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(42) LATS(4180429) Disk lastSeqNo(42)
    [ CSSD]2011-10-30 01:16:08.303 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(42) LATS(4180436) Disk lastSeqNo(42)
    [ CSSD]2011-10-30 01:16:09.172 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(43) LATS(4181304) Disk lastSeqNo(43)
    [ CSSD]2011-10-30 01:16:09.297 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(43) LATS(4181429) Disk lastSeqNo(43)
    [ CSSD]2011-10-30 01:16:09.304 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(43) LATS(4181436) Disk lastSeqNo(43)
    [ CSSD]2011-10-30 01:16:10.172 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(44) LATS(4182305) Disk lastSeqNo(44)
    [ CSSD]2011-10-30 01:16:10.297 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(44) LATS(4182429) Disk lastSeqNo(44)
    [ CSSD]2011-10-30 01:16:10.304 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(44) LATS(4182437) Disk lastSeqNo(44)
    [ CSSD]2011-10-30 01:16:11.173 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(45) LATS(4183305) Disk lastSeqNo(45)
    [ CSSD]2011-10-30 01:16:11.297 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(45) LATS(4183430) Disk lastSeqNo(45)
    [ CSSD]2011-10-30 01:16:11.305 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(45) LATS(4183437) Disk lastSeqNo(45)
    [ CSSD]2011-10-30 01:16:12.173 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(46) LATS(4184305) Disk lastSeqNo(46)
    [ CSSD]2011-10-30 01:16:12.298 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(46) LATS(4184430) Disk lastSeqNo(46)
    [ CSSD]2011-10-30 01:16:12.305 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(46) LATS(4184437) Disk lastSeqNo(46)
    [ CSSD]2011-10-30 01:16:13.173 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(47) LATS(4185306) Disk lastSeqNo(47)
    [ CSSD]2011-10-30 01:16:13.298 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(47) LATS(4185431) Disk lastSeqNo(47)
    [ CSSD]2011-10-30 01:16:13.306 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(47) LATS(4185438) Disk lastSeqNo(47)
    [ CSSD]2011-10-30 01:16:14.174 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(48) LATS(4186306) Disk lastSeqNo(48)
    [ CSSD]2011-10-30 01:16:14.299 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(48) LATS(4186431) Disk lastSeqNo(48)
    [ CSSD]2011-10-30 01:16:14.306 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(48) LATS(4186438) Disk lastSeqNo(48)
    [ CSSD]2011-10-30 01:16:15.174 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(49) LATS(4187307) Disk lastSeqNo(49)
    [ CSSD]2011-10-30 01:16:15.299 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(49) LATS(4187431) Disk lastSeqNo(49)
    [ CSSD]2011-10-30 01:16:15.306 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(49) LATS(4187439) Disk lastSeqNo(49)
    [ CSSD]2011-10-30 01:16:16.175 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(50) LATS(4188307) Disk lastSeqNo(50)
    [ CSSD]2011-10-30 01:16:16.299 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(50) LATS(4188432) Disk lastSeqNo(50)
    [ CSSD]2011-10-30 01:16:16.307 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(50) LATS(4188439) Disk lastSeqNo(50)
    [ CSSD]2011-10-30 01:16:17.175 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(51) LATS(4189308) Disk lastSeqNo(51)
    [ CSSD]2011-10-30 01:16:17.300 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(51) LATS(4189432) Disk lastSeqNo(51)
    [ CSSD]2011-10-30 01:16:17.307 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(51) LATS(4189440) Disk lastSeqNo(51)
    [ CSSD]2011-10-30 01:16:18.176 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(52) LATS(4190308) Disk lastSeqNo(52)
    [ CSSD]2011-10-30 01:16:18.300 [1030] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(52) LATS(4190433) Disk lastSeqNo(52)
    [ CSSD]2011-10-30 01:16:18.308 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(52) LATS(4190440) Disk lastSeqNo(52)
    [ CSSD]2011-10-30 01:16:19.176 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(53) LATS(4191308) Disk lastSeqNo(53)

  3. 张明 Avatar
    张明

    这是在NODE1先启动的情况下,NODE2的日志。

    1. maclean Avatar
      maclean

      以下是 我对这段日志的分析:

      [ CSSD]2011-10-30 01:15:33.906 [1] >TRACE: clssnmNMInitialize: misscount set to (30), impending reconfig threshold set to (26000)
      [ CSSD]2011-10-30 01:15:33.907 [1] >TRACE: clssnmNMInitialize: diskShortTimeout set to (27000)ms
      [ CSSD]2011-10-30 01:15:33.908 [1] >TRACE: clssnmNMInitialize: diskLongTimeout set to (200000)ms

      ———— 这里开始misscount 30s 的计时

      CSSD]2011-10-30 01:15:33.907 [1] >TRACE: clssnmNMInitialize: diskShortTimeout set to (27000)ms
      [ CSSD]2011-10-30 01:15:33.908 [1] >TRACE: clssnmNMInitialize: diskLongTimeout set to (200000)ms

      初始化了 磁盘心跳的超时限制

      [ CSSD]2011-10-30 01:15:35.935 [1801] >TRACE: clssnmvKillBlockThread: spawned for disk 2 (/dev/rhdisk14) initial sleep interval (1000)ms
      [ CSSD]2011-10-30 01:15:35.935 [1030] >TRACE: clssnmDiskStateChange: state from 2 to 4 disk (0//dev/rhdisk12)
      [ CSSD]2011-10-30 01:15:35.935 [2058] >TRACE: clssnmvKillBlockThread: spawned for disk 1 (/dev/rhdisk13) initial sleep interval (1000)ms
      [ CSSD]2011-10-30 01:15:35.935 [2315] >TRACE: clssnmvKillBlockThread: spawned for disk 0 (/dev/rhdisk12) initial sleep interval (1000)ms

      KillBlockThread 初始化, 负责读取 “killblock”

      [ CSSD]2011-10-30 01:15:36.003 [3857] >TRACE: clssgmPeerListener: Listening on (ADDRESS=(PROTOCOL=tcp)(DEV=25)(HOST=10.1.1.2)(PORT=32902))
      [ CSSD]2011-10-30 01:15:35.935 [1544] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(10) LATS(4148068) Disk lastSeqNo(10)
      [ CSSD]2011-10-30 01:15:36.135 [1287] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(1) wrtcnt(10) LATS(4148268) Disk lastSeqNo(10)

      clssnmReadDskHeartbeat 负责读取 磁盘心跳信息, 发现1号节点未写入 Dskhearbeat ,2号节点认为1号节点已经down了

      disktimeout默认为200s (default 200 seconds) , 200s 以后 发生reconfiguration

      这段日志说明 发生网络故障后 , 1号节点未能正常进行 每秒 都需要进行的 Disk Heartbeat , 注意磁盘心跳并非 Brain Split 时才发生 , 关于Disk Heartbeat ( Voting device ) 详见 下面这段描述

      “Disk heartbeat
      Each node writes a disk heartbeat to each voting disk once per second
      Each node reads their kill block once per second, if the kill block is overwritten node commits suicide.
      During reconfig (join or leave) CSSD monitors all nodes and determines whether a node has a disk heartbeat, including those with no network heartbeat.
      If no disk heartbeat within I/O timeout (MissCount during cluster reconfiguration) then node is declared as dead.”

      磁盘心跳超时 会导致 节点被踢 , 这是很正常的 , 这个测试的日志 对 支持” 抢占论” 没有什么意义。

  4. 张明 Avatar
    张明

    感谢Maclean Liu的解释,我明白了,我这个案例跟Brain Split应该没有关系。但我还是想不明白NODE1节点已经起来了并库运行正常,NODE2启动后认为NODE1 DOWN了,为啥自己却重启了呢。若NODE2先启动,NODE1再启动时也会重启,且NODE1上的错误跟这个一样。还好现在把网络恢复后两个节点都起来了。所以还请作者有空帮忙给分析一下可能的原因,谢谢!

  5. ccz320 Avatar

    Hi Maclean,

    看了你的这篇blog,对脑裂后的oracle RAC处理方式有了更深入的理解,但有个问题还有困惑:对第一中方式按照票数计算没有疑问,对于第二个票数相等的情况,如果是rac number较低者得控制权,那么仲裁盘在整个算法中又起什么作用呢?请帮忙解释下,谢谢!

    1. Maclean Liu Avatar

      不要被 仲裁盘这个名称误导了。 试想若没有vote disk,在network heartbeat不可用的情况下, cluster分裂成多个 subcluster时, 它们如何知道对方的subcluster中node的数量呢? 它们如何发送killblock 以实现evicte驱逐通知呢?

      详见 http://www.oracledatabase12g.com/archives/oracle-rac-brain-split-resolution.html

  6. ppomm Avatar
    ppomm

    版本是11.2.0.4的

  7. zergduan Avatar
    zergduan

    “子节点号之和最小的子集群被保留,其他子集群被驱逐~” 这样的规则适用于10g到12.0.1.1;从12.0.1.2开始这个规则被颠倒变成为“子节点号之和最大的子集群被保留,其他子集群被驱逐~”

    1. zergduan Avatar
      zergduan

      写错了,应该是12.0.1.2开始先比较node weight,如果weight不同,weight高的被保留,其他被驱逐~
      如果node weight相同,那么还是节点号之最小的被保留,其他的被驱逐~

      1. Maclean Liu Avatar

        是的,对于12c的改变 这边文章需要做更新才能适合12c以后的集群脑裂算法了。

Leave a Reply

Your email address will not be published. Required fields are marked *