Brain Split?

Hdr: 8293652 10.2.0.3 PCW 10.2.0.3 OSD PRODID-5 PORTID-46 Abstract: CSS CANNOT HANDLE SPLIT-BRAIN AND DB INSTANCE RECEIVES ORA-29740 PROBLEM: -------- config: 2-node RAC: Node1 (pdb01) and Node2 (pdb02) There's no time difference between two nodes. pdb02 got ORA-29740 and terminated at "Tue Feb 17 12:13:06 2009" ORA-29740 occured with reason 1. After ORA-29740 happened, the instance won't be able to start until rebooting OS. After rebooting OS, everything was fine and instances were up. DIAGNOSTIC ANALYSIS: -------------------- clssnmReadDskHeartbeat: node(2) is down. rcfg(8) wrtcnt(2494425) LATS(1205488794) Disk lastSeqNo(2494425) nodes clssgmMasterSendDBDone: group/lock status synchronization complete nodes WORKAROUND: ----------- none RELATED BUGS: ------------- REPRODUCIBILITY: ---------------- once at ct's env. TEST CASE: ---------- STACK TRACE: ------------ SUPPORTING INFORMATION: ----------------------- 24 HOUR CONTACT INFORMATION FOR P1 BUGS: ---------------------------------------- DIAL-IN INFORMATION: -------------------- IMPACT DATE: ------------ Does ct apply any CRS(bundle) patch ? When problem happen, cssd can't connect each other via interconnect, but both cssd can do heartbeat to voting disk. However, both cssd consider that "I'm survivor". Looking into node 1 cssd. * 12:02:30.856 - Initiated sync [ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate: Initiating sync 7 [ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate: diskTimeout set to (57000)ms * Checking voting disk, and find node2 is still voting and living. [ CSSD]2009-02-17 12:02:30.874 [1262557536] >TRACE: clssnmCheckDskInfo: Checking disk info... [ CSSD]2009-02-17 12:02:30.874 [1262557536] >TRACE: clssnmCheckDskInfo: node(2) timeout(20) state_network(5) state_disk(3) misstime(0) [ CSSD]2009-02-17 12:02:31.878 [1262557536] >TRACE: clssnmCheckDskInfo: node(2) disk HB found, network state 5, disk state(3) misstime(1010) * Compared cluster size and confirmed it can survive. [ CSSD]2009-02-17 12:02:34.885 [1262557536] >TRACE: clssnmCheckDskInfo: node 2, iz-pdb02, state 5 with leader 2 has smaller cluster size 1; my cluster size 1 with leader 1 * Then finished [ CSSD]2009-02-17 12:02:34.886 [1262557536] >TRACE: clssnmDoSyncUpdate: Sync Complete! *** 03/08/09 11:23 pm *** Looking into node 2 cssd log. * 12:02:20.647 - initiated sync protocol [ CSSD]2009-02-17 12:02:20.647 [1262557536] >TRACE: clssnmDoSyncUpdate: Initiating sync 7 [ CSSD]2009-02-17 12:02:20.647 [1262557536] >TRACE: clssnmDoSyncUpdate: diskTimeout set to (57000)ms * Checking disk and find node1 does not do disk heartbeart for 59690 ms. it would have waited for misscount and considered node 1 is dead [ CSSD]2009-02-17 12:02:22.285 [1262557536] >TRACE: clssnmCheckDskInfo: Checking disk info... [ CSSD]2009-02-17 12:02:22.285 [1262557536] >TRACE: clssnmCheckDskInfo: node(1) timeout(59690) state_network(5) state_disk(3) misstime(61000) * node2 is the only active member of cluster, finished. [ CSSD]2009-02-17 12:02:22.723 [1262557536] >TRACE: clssnmDoSyncUpdate: Sync Complete! *** 03/08/09 11:45 pm *** So, strange point is, node 2 cssd says node 1 cssd didn't do disk heartbeat for 60 seconds. Looking into node1 cssd log just before initiating sync. We see 87sec gap. ----------------------------------- [ CSSD]2009-02-17 12:00:19.354 [1199618400] >TRACE: clssgmClientConnectMsg: Connect from con(0x784d80) proc(0x7749b0) pid(14746) proto(10:2:1:1) [ CSSD]2009-02-17 12:00:33.338 [1199618400] >TRACE: clssgmClientConnectMsg: Connect from con(0x7d8620) proc(0x75cfb0) pid() proto(10:2:1:1) [ CSSD]2009-02-17 12:01:03.688 [1199618400] >TRACE: clssgmClientConnectMsg: Connect from con(0x76a390) proc(0x75cfb0) pid(13634) proto(10:2:1:1) [ CSSD]2009-02-17 12:02:30.855 [1168148832] >WARNING: clssnmDiskPMT: sltscvtimewait timeout (69200) [ CSSD]2009-02-17 12:02:30.855 [1189128544] >WARNING: clssnmeventhndlr: Receive failure with node 2 (iz-pdb02), state 3, con(0x72b980), probe((nil)), rc=10 [ CSSD]2009-02-17 12:02:30.855 [1189128544] >TRACE: clssnmDiscHelper: iz-pdb02, node(2) connection failed, con (0x72b980), probe((nil)) [ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate: Initiating sync 7 As an interesting point, clssgmClientConnectMsg does not show message, but nm polling thread/disk ping thread does not warn timeout. (Usually it should write message first at 50% of timeout = 30 sec) And "sltscvtimewait timeout (69200)" message means, DiskPingMonitor thread does not run for a 69200 ms whereas it just wants to sleep 1 second. These suggest, cssd does not scheduled about 70 seconds on node 1. I don't see any log from DiskPingThread, but I assume it is suspended at some point also, and back to work after 70 seconds. Please check OS message file to see any interesting error is recorded. To prevent this issue, keep watching OS performance to see if any extreme high load does not happen. Recommended solution it to go to 10.2.0.4 and use oprocd so that we can expect oprocd kill node1 in such case.

    上述案例同样是在"cssd can't connect each other via interconnect"的状况下出现了"I'm survivor"的脑裂问题，MOS的建议是升级到10204后oprocd进程可以阻止这样的惨剧发生。   该问题最后通过升级到10.2.0.5解决了，这个case告诉我们在中国的it大环境内，有时候我们不得不亲力亲为地关心每一个细节，就拿这次来说我一开始也没发现升级没完成的情况，后来还是同事提醒了我；因为这是一个非常低级错误，如果施工方的X码工程师仔仔细细地按照他们下发的文档按部就班亦或者能留意一下升级时的图形窗口中的说明的话，这个问题都不会发生！而实际上不仅仅是此套系统，连带着其他2套系统也是这位X码工程师安装升级的，这几套系统在之后的故障测试时都发现了同样的问题。 事实告诉我们，细节决定成败！

本文转自maclean_007 51CTO博客，原文链接:http://blog.51cto.com/maclean/1277131