技術培訓 | RAC 當機罪犯案情探析之子游標

arron劉發表於2016-06-16

大家好，我是雲和恩墨的李軼楠，不過網上的朋友更習慣叫我600，所以我也慢慢熟悉了這個稱呼，其實這個稱呼來自於ITPUB論壇上當時我註冊的論壇ID“ORA-600”，因為這個ID跟Oracle的著名錯誤號一樣，很容易給大家留下深刻印象，所以被我借用了過來，呵呵。這些年透過論壇上認識了很多朋友，也結識了現在與我一起奮戰的恩墨小夥伴們。
閒話不多說，我們來看看我們今天要分享的主題吧，這些年我們積累了大量的客戶群體，也意味著我們面對著各種複雜的環境與事件，後續我會把我們小夥伴們所遭遇到的各種或者經典、或者靈異、或者有趣的case，逐一做成案件分析來分享給大家，希望大家喜歡。今天就以去年我們所遇到的一次RAC節點當機的故障作為開場吧。

1. 案情描述

2015年6月的一個傍晚，大雨滂沱，正坐在家裡發呆中，突然被一陣鈴聲驚醒。拿起電話，發現是客戶來電，於是趕緊接聽：
”我們的核心繫統在晚上9點多突然有一個節點掛了，例項自動重啟。雖然沒有影響業務，但這種無緣無故的重啟發生在核心繫統上，直接威脅我們的業務執行，領導很重視，所以今天必須把原因找到，多晚都要給出結果，拜託了！“

2. 案情分析

聽到客戶的描述，心裡第一個反應是：還好，只是單節點重啟，問題本身應該不嚴重，至少對業務影響並不大，看來這大雨天是不用淋雨去客戶現場了。。。呵呵，小心思而已。
客戶目前急需的是快速給出問題的原因，以便根據情況作出後續的規避措施，所以需要儘快拿到現場的一些資料來做分析，畢竟分析所需要的資訊資料距離故障時間越近，精準度就越高，越有利分析。

經過進一步的溝通，得到了一些案發時的基本資訊：

  1. 重啟的是整個資料庫架構的2節點，這個庫是核心系統，晚上也有業務；
  2. 重啟例項的情況其實以前也發生過，只不過發生的不多；（潛臺詞是也許這不是個案，以前的重啟意味著可能這個問題一直存在）
  3. 當前資料庫版本為11.2.0.1。（看到每個大版本的第一個小版本，總是覺得這種系統會BUG纏身。。。雖然誇大了點，但我們確實遇到了不少這種小版本的BUG）

當然，很明顯只聽客戶描述是不夠的。於是，我遠端登入了客戶的伺服器，開始做進一步檢查。
在開始分析之前，先跟大家及一下故障分析的常規思路，也便於初學者在遇到問題的時候知道從何處入手。

  • 在遇到故障時，首先要辨識一下當前的場景主要是效能問題的還是真的故障；
  • 如果是效能問題，那就需要收集當時的系統效能資訊與資料庫效能資訊，awr、ash，或者系統的nmon、top之類都可以；
  • 如果是故障，那就要檢查資料庫的告警日誌與跟蹤檔案了，非常典型的就是alertSID.log，這裡面往往給了我們進一步追蹤痕跡的指引。除此之外，各個程式的trace檔案，asm的trace檔案以及RAC的各種log、trace檔案都會給出一些故障的原因或者印記，具體的這些檔案所在目錄大家都應該熟悉，最典型的就是透過background_dump_dest、user_dump_dest引數去查詢（注意，rac的log和trace檔案與資料庫的目錄並不在一起，可以檢查$GRID_HOME/log/<hostname>的各個子目錄），更詳細的在這裡就不再展開了。
  • 另外，當遭遇這些問題的時候，如果有MOS賬號的話，建議首先去MOS中檢視是否有故障相關的BUG或者技術文章，這既是快速診斷問題、解決問題的途徑，也是DBA快速成長的重要手段。關於MOS的使用，大家可以加公眾號“oracle”，在其中可以看到5月5日發的一篇“Oracle初學者入門指南-什麼是Metalink或MOS？”

好吧，回到我們的案例中：

1、下面是節點2的alert log部分內容： 

Fri Jun 26 20:24:52 2015
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_p001_13581.trc  (incident=204565):
 ORA-00600: 內部錯誤程式碼, 引數: [kksfbc-wrong-kkscsflgs], [39913467504], [33], [], [], [], [], [], [], [], [], []
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204565/orcl2_p001_13581_i204565.trc
 Fri Jun 26 20:25:06 2015
 Trace dumping is performing id=[cdmp_20150626202506]
 Fri Jun 26 20:25:06 2015
 Sweep [inc][204565]: completed
 Sweep [inc2][204565]: completed
 Fri Jun 26 20:25:18 2015
 Trace dumping is performing id=[cdmp_20150626202517]
 。。。。。
 Fri Jun 26 21:21:08 2015
 Archived Log entry 164580 added for thread 2 sequence 48360 ID 0xa822d65a dest 1:
 Fri Jun 26 21:41:09 2015
 Thread 2 advanced to log sequence 48362 (LGWR switch)
   Current log# 2 seq# 48362 mem# 0: +DATA/orcl/onlinelog/redo21.log
   Current log# 2 seq# 48362 mem# 1: +DATA/orcl/onlinelog/redo22.log
 Fri Jun 26 21:41:09 2015
 Archived Log entry 164584 added for thread 2 sequence 48361 ID 0xa822d65a dest 1:
 Fri Jun 26 21:50:26 2015
 LCK0 (ospid: 29987) waits for latch 'object queue header operation' for 77 secs.
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204141):
 ORA-29771: process MMON (OSID 29967) blocks LCK0 (OSID 29987) for more than 70 seconds
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204141/orcl2_lmhb_29939_i204141.trc
 MMON (ospid: 29967) is blocking LCK0 (ospid: 29987) in a wait
 LMHB (ospid: 29939) kills MMON (ospid: 29967).
 Please check LMHB trace file for more detail.
 Fri Jun 26 21:51:06 2015 Restarting dead background process MMON
 Fri Jun 26 21:51:06 2015 MMON started with pid=213, OS id=16612 Fri Jun 26 21:51:09 2015 Sweep [inc][204141]: completed
 Sweep [inc2][204141]: completed
 Fri Jun 26 21:54:10 2015 LMS1 (ospid: 29929) waits for latch 'object queue header operation' for 81 secs.
 LCK0 (ospid: 29987) has not called a wait for 85 secs. Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204142):
 ORA-29770: global enqueue process LMS1 (OSID 29929) is hung for more than 70 seconds
  Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204142/orcl2_lmhb_29939_i204142.trc
 Fri Jun 26 21:54:20 2015 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204143):
 ORA-29770: global enqueue process LCK0 (OSID 29987) is hung for more than 70 seconds
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204143/orcl2_lmhb_29939_i204143.trc
 ERROR: Some process(s) is not making progress.
 LMHB (ospid: 29939) 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.
 LMHB (ospid: 29939): terminating the instance due to error 29770 Fri Jun 26 21:54:21 2015 opiodr aborting process unknown ospid (26414) as a result of ORA-1092 Fri Jun 26 21:54:21 2015 ORA-1092 : opitsk aborting process
 Fri Jun 26 21:54:21 2015 System state dump is made for local instance
 System State dumped to trace file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_29889.trc
 Instance terminated by LMHB, pid = 29939 Sat Jun 27 12:52:23 2015 Starting ORACLE instance (normal)
 LICENSE_MAX_SESSION = 0 LICENSE_SESSIONS_WARNING = 0 Interface type 1 eth1 172.16.0.0 configured from GPnP Profile for use as a cluster interconnect
 Interface type 1 eth0 192.168.0.128 configured from GPnP Profile for use as a public interface
 Picked latch-free SCN scheme 3 Autotune of undo retention is turned on.
 LICENSE_MAX_USERS = 0 SYS auditing is disabled

在告警日誌中我們發現一個很明顯的ORA-600錯誤，同時也發現一些其他的ORA報錯，見上面標紅部分。於是我們對這些錯誤分別進行了分析，發現：

1）ORA-600 [kksfbc-wrong-kkscsflgs] (Doc ID 970885.1) 確實是一個bug，在MOS上有說明：

NB Bug Fixed Description
9067282 11.2.0.1.2, 11.2.0.1.BP01, 11.2.0.3, 12.1.0.1 ORA-600 [kksfbc-wrong-kkscsflgs] can occur
9066130 10.2.0.5, 11.1.0.7.2, 11.2.0.2, 12.1.0.1 OERI [kksfbc-wrong-kkscsflgs] / spin with multiple children
8828328 11.2.0.1.1, 11.2.0.1.BP04, 11.2.0.2, 12.1.0.1 OERI [kksfbc-wrong-kkscsflgs]
8661168 11.2.0.1.1, 11.2.0.1.BP01, 11.2.0.2, 12.1.0.1 OERI[kksfbc-wrong-kkscsflgs] can occur

但MOS上並未說明該BUG會導致例項當機，這個600錯誤看來應該與此次重啟關係不大，好吧，作為一個問題記下來就是了。

2） 在故障時間點，LMHB 程式check發現mmon程式阻塞了LCK0程式，超過70s，因此嘗試kill MMON程式，該程式被kill之後將會自動重啟。
可以看到在Jun 26 21:51:06 時間點，MMON程式重啟完成。

這裡在插播一件事，正好就在前幾天，我們的客戶也遇到了MMON程式的相關問題，在這也順便分享給大家：客戶的MMON程式被Kill之後並未自動啟動，導致AWR等效能資訊無法自動收集，因此客戶希望能夠在不啟動資料庫的情況下啟動MMON，再想了各種辦法之後，最終找到了方法： 

Restart the database instance

或者 

Set the instance to "restricted session" mode and then bring it back to normal mode using following commands as SYSDBA: alter system enable restricted session; alter system disable restricted session;

大家也可以搜尋一下MOS上的文章，看到相關的資訊：文件 ID 2023652.1

接下來，在Jun 26 21:54:10，LMS1程式報錯無法獲得latch（object queue header operation） 超過85秒。

注: LMHB是11gR2中引入的後臺程式，官方文件介紹是Global Cache/Enqueue Service Heartbeat Monitor，Monitor the heartbeat of LMON, LMD, and LMSn processes，LMHB monitors LMON, LMD, and LMSn processes to ensure they are running normally without blocking or spinning。 該程式負責監控LMON、LMD、LMSn等RAC關鍵的後臺程式，保證這些background process不被阻塞或spin。 LMHB是Lock Manager Heartbeat的縮寫。

2、為了更清楚的理清線索，我們根據節點2的alert log資訊，整理出如下的時間線點： 

Jun 26 20:24:52 ORA-00600 [kksfbc-wrong-kkscsflgs]
Jun 26 21:50:26 LCK0 (ospid: 29987) waits for latch 'object queue header operation' for 77 secs MMON (OSID 29967) blocks LCK0 (OSID 29987) for more than 70 seconds MMON (ospid: 29967) is blocking LCK0 (ospid: 29987) in a wait LMHB (ospid: 29939) kills MMON (ospid: 29967) Jun 26 21:51:06   MMON started with pid=213, OS id=16612 Jun 26 21:54:10 LMS1 (ospid: 29929) waits for latch 'object queue header operation' for 81 secs LCK0 (ospid: 29987) has not called a wait for 85 secs
                  ORA-29770: global enqueue process LMS1 (OSID 29929) is hung for more than 70 seconds
                  
Jun 26 21:54:20   ORA-29770: global enqueue process LCK0 (OSID 29987) is hung for more than 70 seconds
                  ERROR: Some process(s) is not making progress. LMHB (ospid: 29939) is terminating the instance LMHB (ospid: 29939): terminating the instance due to error 29770

從最後的資訊可以看出,在21:54:20時間點，LMHB程式強行終止了資料庫例項. 而終止例項的原因是LMHB程式發現LCK0進行hung住了，而且超過了70s。在從前面的資訊也可以看出，實際上在21:54:10時間點，LCK0程式就已經沒有活動了了，而且在該時間點LMS1程式也一直在等待latch。很明顯，如果LMS1程式無法正常工作，Oracle為了保證叢集資料的一致性，為了避免腦裂，必然將問題節點強行驅逐重啟。
那麼LMS1在等什麼呢？LCK0為什麼被Hung住了？

3、lms1程式的情況

讓我們來看看LMS1到底在幹什麼？
檢查orcl2_lmhb_29939_i204142.trc，而該trace 檔案產生的時間點是：Jun 26 21:54:10： 

SO: 0x9a1175160, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
 proc=0x9a1175160, name=process, file=ksu.h LINE:11459, pg=0
(process) Oracle pid:14, ser:1, calls cur/top: 0x9b17e5330/0x9b17e0e60
          flags : (0x6) SYSTEM
          flags2: (0x100),  flags3: (0x0) 
          intr error: 0, call error: 0, sess error: 0, txn error 0 intr queue: empty
ksudlp FALSE at location: 0 (post info) last post received: 0 0 116 last post received-location: kjc.h LINE:1810 ID:KJCS Post snd proxy to flush msg last process to post me: 991126330 1 6 last post sent: 41134582880 162 1 last post sent-location: ksl2.h LINE:2160 ID:kslges last process posted by me: 9811032c8 1 14 (latch info) wait_event=0 bits=a
        Location from where call was made: kcbo.h LINE:890 ID:kcbo_unlink_q_bg: 
    waiting for 993cfec60 Child object queue header operation level=5 child#=117 Location from where latch is held: kcl2.h LINE:3966 ID:kclbufs: 
        Context saved from call: 0 state=busy(shared) [value=0x4000000000000001] wlstate=free [value=0]
        waiters [orapid (seconds since: put on list, posted, alive check)]: 14 (95, 1435326858, 4) 21 (94, 1435326858, 7)
         waiter count=2 gotten 73961423 times wait, failed first 4752 sleeps 1927 gotten 33986 times nowait, failed: 4 possible holder pid = 36 ospid=29987 on wait list for 993cfec60
    holding    (efd=5) 9b59be480 Child gc element level=3 child#=20 Location from where latch is held: kcl2.h LINE:3535 ID:kclbla: 
        Context saved from call: 0 state=busy(exclusive) [value=0x200000000000000e, holder orapid=14] wlstate=free [value=0]
    holding    (efd=5) 9b45cac50 Child cache buffers chains level=1 child#=61221 Location from where latch is held: kcl2.h LINE:3140 ID:kclbla: 
        Context saved from call: 0 state=busy(exclusive) [value=0x200000000000000e, holder orapid=14] wlstate=free [value=0]
  Process Group: DEFAULT, pseudo proc: 0x9b11ca008 O/S info: user: oracle, term: UNKNOWN, ospid: 29929 OSD pid info: Unix process pid: 29929, image: oracle@ebtadbsvr2 (LMS1)

從LMS1程式的資訊來看，LMS1 程式所等待的資源（object queue header operation）正被ospid=29987 持有，那麼29987又是什麼呢？

4、進一步分析下ospid=29987 是什麼？

讓我們接著往下看： 

 SO: 0x9911283b0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
 proc=0x9911283b0, name=process, file=ksu.h LINE:11459, pg=0
(process) Oracle pid:36, ser:2, calls cur/top: 0x9b17e58e0/0x9b17e58e0
          flags : (0x6) SYSTEM
          flags2: (0x0),  flags3: (0x0) 
          intr error: 0, call error: 0, sess error: 0, txn error 0 intr queue: empty
ksudlp FALSE at location: 0 (post info) last post received: 0 0 35 last post received-location: ksr2.h LINE:603 ID:ksrpublish last process to post me: 981110608 118 0 last post sent: 0 0 36 last post sent-location: ksr2.h LINE:607 ID:ksrmdone last process posted by me: 9911283b0 2 6 (latch info) wait_event=0 bits=20 holding    (efd=3) 993cfec60 Child object queue header operation level=5 child#=117 Location from where latch is held: kcl2.h LINE:3966 ID:kclbufs: 
        Context saved from call: 0 state=busy(shared) [value=0x4000000000000001] wlstate=free [value=0]
        waiters [orapid (seconds since: put on list, posted, alive check)]: 14 (95, 1435326858, 4) 21 (94, 1435326858, 7)
         waiter count=2 Process Group: DEFAULT, pseudo proc: 0x9b11ca008 O/S info: user: oracle, term: UNKNOWN, ospid: 29987 OSD pid info: Unix process pid: 29987, image: oracle@ebtadbsvr2 (LCK0)

最後一句很明顯的告訴我們，29987原來就是LCK0程式。這意味著lms1 程式所等待的資源正被LCK0 程式所持有。而同時還有另外一個程式orapid=21 也在等待該程式。透過分析我們分析發現：
orapid=21，是dbw2程式，即資料庫寫程式。

注：這裡解釋一下，orapid是oracle中的程式id，而pid則是os上的程式id。所以orapid=21從v$process中可以查到是dbw2，而orapid=14是lms1.

5、從資料庫alert log來看，在Jun 26 21:54:10 有提示lck0 程式已經超過85秒沒有響應 

LCK0 (ospid: 29987) has not called a wait for 85 secs

根據時間點來計算，大概在Jun 26 21:52:45點左右開始，LCK0程式即沒有響應了。
那麼很明顯，我們只要知道LCK0程式為什麼會hung，就知道了此次故障的原因。
那麼我們來看看LCK0的trace檔案，看能不能看到一些線索。

6、LCK0程式的trace資訊 

*** 2015-06-26 21:50:29.329 Process diagnostic dump for oracle@ebtadbsvr2 (LCK0), OS id=29987,  
pid: 36, proc_ser: 2, sid: 1729, sess_ser: 3 -------------------------------------------------------------------------------                                             
loadavg : 6.47 26.96 34.97 Memory (Avail / Total) = 10598.05M / 64421.55M                           
Swap (Avail / Total) = 20256.00M / 20479.99M            
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD 0 S oracle 29987 1 0 76 0 - 10541946 semtim Apr05 ? 01:25:21 ora_lck0_orcl2 
Short stack dump: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semop()+7<-skgpwwait()+156<-kslgess()+1799<-ksl_get_shared_latch()+620<-kclbufs()+272<-kclanticheck()+412<-kclahrt()+88<-ksbcti()+212<-ksbabs()+1732<-kclabs()+186<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+214<-main()+201<-__libc_start_main()+244<-_start()+36 *** 2015-06-26 21:54:18.438 Process diagnostic dump for oracle@ebtadbsvr2 (LCK0), OS id=29987,
pid: 36, proc_ser: 2, sid: 1729, sess_ser: 3 -------------------------------------------------------------------------------
loadavg : 2.04 13.34 27.63 Memory (Avail / Total) = 9519.06M / 64421.55M
Swap (Avail / Total) = 20256.00M / 20479.99M
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD 0 R oracle 29987 1 0 85 0 - 10541965 ?   Apr05 ? 01:26:55 ora_lck0_orcl2
Short stack dump: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-kcbo_get_next_qheader()+255<-kclbufs()+321<-kcldirtycheck()+231<-kclahrt()+93<-ksbcti()+212<-ksbabs()+1732<-kclabs()+186<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+214<-main()+201<-__libc_start_main()+244<-_start()+36

從上述lck0程式的幾個時間點的資訊來看，第一個時間點21:50:29 ：wchan 為semtim。wchan，表示程式sleeping的等待表現形式。semtim表示在該時間點，lck0 程式一直處於sleep狀態。所謂的sleep狀態，是程式持有的資源是不會釋放的。

而在第2個時間點21:54:18，lck0程式的wchan狀態是 ?，這表示未知，如果是為空，則表示該程式處理running狀態。在21：50到21：52 時間段內，LCK0程式仍然沒有恢復正常。那麼LCK0到底被什麼阻塞了（或者說它需要的資源被誰佔用了）？
同時也可以看到記憶體和swap都空閒很多，CPU也並不很忙。

7、繼續檢查trace，在21：50時間點我們發現，lck0程式是被MMON程式鎖阻塞了 

SO: 0x9d10f97c0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
 proc=0x9d10f97c0, name=process, file=ksu.h LINE:11459, pg=0
(process) Oracle pid:31, ser:1, calls cur/top: 0x965657408/0x9b17e3f18
          flags : (0x2) SYSTEM
          flags2: (0x20),  flags3: (0x0) 
          intr error: 0, call error: 0, sess error: 0, txn error 0 intr queue: empty
ksudlp FALSE at location: 0 (post info) last post received: 0 0 35 last post received-location: ksr2.h LINE:603 ID:ksrpublish last process to post me: 9911283b0 2 6 last post sent: 0 0 26 last post sent-location: ksa2.h LINE:282 ID:ksasnd last process posted by me: 9911283b0 2 6 (latch info) wait_event=0 bits=26 holding    (efd=7) 993cfec60 Child object queue header operation level=5 child#=117 Location from where latch is held: kcbo.h LINE:884 ID:kcbo_link_q: 
        Context saved from call: 0 state=busy(exclusive) [value=0x200000000000001f, holder orapid=31] wlstate=free [value=0]
        waiters [orapid (seconds since: put on list, posted, alive check)]: 36 (82, 1435326627, 1) 21 (81, 1435326627, 1)
         waiter count=2 holding    (efd=7) 9b5a5d630 Child cache buffers lru chain level=2 child#=233 Location from where latch is held: kcb2.h LINE:3601 ID:kcbzgws: 
        Context saved from call: 0 state=busy [holder orapid=31] wlstate=free [value=0]
    holding    (efd=7) 9c2a99938 Child cache buffers chains level=1 child#=27857 Location from where latch is held: kcb2.h LINE:3214 ID:kcbgtcr: fast path (cr pin): 
        Context saved from call: 12583184 state=busy(exclusive) [value=0x200000000000001f, holder orapid=31] wlstate=free [value=0]
  Process Group: DEFAULT, pseudo proc: 0x9b11ca008 O/S info: user: oracle, term: UNKNOWN, ospid: 29967 OSD pid info: Unix process pid: 29967, image: oracle@ebtadbsvr2 (MMON)

從上面的trace可以看到之前一直被等待的993cfec60 資源（Child object queue header operation）正被 mmon程式持有。

21:50:29的時候LCK0在等待mmon釋放資源，而此時mmon出現異常，因此在21:51:06 mmon 程式被LMHB強制重啟。然後在重啟後，由於mmon的異常，導致21:54:18該資源仍無法被lck0 程式正常持有，最終導致21:54:20LMHB程式強制重啟了整個例項。
因此，最終的罪魁禍首是mmon程式。 

Fri Jun 26 21:50:26 2015 LCK0 (ospid: 29987) waits for latch 'object queue header operation' for 77 secs.
 Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_lmhb_29939.trc  (incident=204141):
 ORA-29771: process MMON (OSID 29967) blocks LCK0 (OSID 29987) for more than 70 seconds
 Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl2/incident/incdir_204141/orcl2_lmhb_29939_i204141.trc MMON (ospid: 29967) is blocking LCK0 (ospid: 29987) in a wait LMHB (ospid: 29939) kills MMON (ospid: 29967).
 Please check LMHB trace file for more detail.
 Fri Jun 26 21:51:06 2015
 Restarting dead background process MMON
 Fri Jun 26 21:51:06 2015
 MMON started with pid=213, OS id=16612

mmon程式Oracle是用於進行AWR資訊收集的。既然案情發生的原因與它有關，那麼接下來的分析自然是檢視它的相關trace了。

8、檢查MMON的相關trace 可以看到，MMON程式負責處理物件的統計資訊。

從trace中可以看到大量的cursor包含了太多的子游標，例如： 

User=b1456358 Session=c146d760 ReferenceCount=1 Flags=CNB/[0001] SavepointNum=558d5760 
      LibraryHandle:  Address=2f79eb08 Hash=3dec6f4a LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
        ObjectName:  Name=        select time_mp, scn, num_mappings, tim_scn_map from smon_scn_time   where scn =    (select max(scn) from smon_scn_time where scn <= :1) FullHashValue=c36d5a579fdc3e19733192893dec6f4a Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=1038905162 OwnerIdn=0 Statistics: InvalidationCount=0 ExecutionCount=23741 LoadCount=107 ActiveLocks=1 TotalLockCount=6093 TotalPinCount=1 Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=106 KeepHandle=106 BucketInUse=6092 HandleInUse=6092 Concurrency: DependencyMutex=2f79ebb8(0, 0, 0, 0) Mutex=2f79ec30(0, 87578, 0, 0) Flags=RON/PIN/TIM/PN0/DBN/[10012841] WaitersLists: Lock=2f79eb98[2f79eb98,2f79eb98] Pin=2f79eba8[2f79eb78,2f79eb78] Timestamp: Current=04-05-2015 09:48:42 LibraryObject: Address=dff3bc60 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000] ChildTable: size='112' Child: id='0' Table=dff3cb60 Reference=dff3c5b0 Handle=2f79e908 Child: id='1' Table=dff3cb60 Reference=dff3c8e0 Handle=2f4e2d90 Child: id='2' Table=dff3cb60 Reference=df3e7400 Handle=2f8c9e90 Child: id='3' Table=dff3cb60 Reference=df3e76e8 Handle=2f8abce8 ...... ...... Child: id='101' Table=dc86f748 Reference=df02d368 Handle=288e6460 Child: id='102' Table=dc86f748 Reference=dd65c3e0 Handle=274d0b40 Child: id='103' Table=dc86f748 Reference=dd65c6c8 Handle=29aa92f8 Child: id='104' Table=dc86f748 Reference=dd65c9b8 Handle=26f3a460 Child: id='105' Table=dc86f748 Reference=dd65ccd0 Handle=25c02dd8 NamespaceDump: Parent Cursor: sql_id=76cckj4yysvua parent=0x8dff3bd48 maxchild=106 plk=y ppn=n Current Cursor Sharing Diagnostics Nodes: ...... ...... Child Node: 100 ID=34 reason=Rolling Invalidate Window Exceeded(2) size=0x0 already processed: Child Node: 101 ID=34 reason=Rolling Invalidate Window Exceeded(2) size=0x0 already processed:

類似上面的資訊非常多。很明顯，上述parent cursor包含了大量的子游標，這是為什麼在20點-21點（節點2還未重啟前的時段）的awr報告中出現大量cursor: mutex S 的原因，如下是這個時段的等待事件：

Event Waits Time(s) Avg wait (ms) % DB time Wait Class
DB CPU 47,072 93.05
cursor: mutex S 31,751,317 18,253 1 36.08 Concurrency
gc cr multi block request 359,897 1,281 4 2.53 Cluster
gc buffer busy acquire 10,465 686 66 1.36 Cluster
library cache lock 9,285 550 59 1.09 Concurrency

在mmon正常透過內部SQL收集系統資訊時，根本不應該出現這種情況，而此時MMON程式卻出現異常，這個異常看來應該是與cursor子游標過多有關了。

9、最後資料庫例項被強行終止的原因是lck0程式出現異常導致lmhb程式強行終止instance
在最後instance終止之前的diag dump中，lck0程式的狀態仍然是hang的狀態，同時也阻塞了3個其他session，如下： 

 SO: 0x9914dbce8, type: 4, owner: 0x9911283b0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3 proc=0x9911283b0, name=session, file=ksu.h LINE:11467, pg=0 (session) sid: 1729 ser: 3 trans: (nil), creator: 0x9911283b0 flags: (0x51) USR/- flags_idl: (0x1) BSY/-/-/-/-/- flags2: (0x408) -/- DID: , short-term DID: 
              txn branch: (nil) oct: 0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS
    ksuxds FALSE at location: 0 service name: SYS$BACKGROUND
    Current Wait Stack:
      Not in wait; last wait ended 1 min 39 sec ago 
    There are 3 sessions blocked by this session.
    Dumping one waiter: inst: 2, sid: 1009, ser: 1 wait event: 'latch: object queue header operation' p1: 'address'=0x993cfec60 p2: 'number'=0xa2 p3: 'tries'=0x0 row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0 min_blocked_time: 81 secs, waiter_cache_ver: 14285 Wait State:
      fixed_waits=0 flags=0x20 boundary=(nil)/-1

對於資料庫程式，如果狀態不是dead，而是busy，而且持有latch不釋放，那麼這意味著該程式已被掛起，lck0 持有的latch是object queue header operation。oracle mos文件也有關於該event 的描述如下：Scans of the object queue in the buffer cache can hold the "object queue header operation"。

基於上述的分析，我們最終判斷，lck0 程式出現問題的原因與cursor 子游標過多有關。同時，這又與在11.2.0.1版本上的child cursor總數閥值限制過高有關（實際在版本10g中就引入了該Cursor Obsolescence遊標廢棄特性，10g的child cursor 的總數閥值是1024，即子游標超過1024即被過期，但是這個閥值在11g的初期版本中被移除了。這就導致出現一個父遊標下大量child cursor即high version count的發生；由此引發了一系列的版本11.2.0.3之前的cursor sharing 效能問題。這意味著版本11.2.0.1和11.2.0.2的資料庫，將可能出現大量的Cursor: Mutex S 和 library cache lock等待事件這種症狀，進而誘發其他故障的發生。

因此， 強烈建議11.2.0.3以下的版本應儘快將資料庫版本升級到11.2.0.3以上（11.2.0.3中預設就有”_cursor_obsolete_threshold”了，而且預設值為100），或者透過_cursor_features_enabled 和106001 event來強制控制子游標過多的情況。

3. 結案陳詞

該案例的分析還是有些曲折，因為常見導致單節點故障最常見的情況主要是心跳、節點資源之類，而該案例的誘發原因相對有些詭異，先是出現了ora-600錯誤，然後又報了kill mmon的資訊，這都讓案情分析有些撲朔迷離，當然，最終我們還是找出了問題的主要根源。

透過該起案件我們發現：

  1. 資料庫版本的選擇絕對是影響系統穩定性的關鍵要點；
  2. 不要以為效能問題只是影響使用者體驗，有些效能問題是會誘發系統一系列問題的；
  3. 問題的分析不要想當然，透過trace逐步遞進，結合原理與經驗，才能更為準確的確定問題；
  4. 子游標過多千萬不能小視，最好能找出根源並解決它，如果確實不好解決，那麼可透過設定隱含引數_cursor_features_enabled 和106001 event強制失效子游標的方式來防止子游標過多的情況，操作如下： 
SQL> alter system set "_cursor_features_enabled"=300 scope=spfile;
SQL> alter system set event='106001 trace name context forever,level 1024' scope=spfile;

正常重啟資料庫即可。

Q&A

1、在什麼情況下可以重用父遊標和子游標呢？

父遊標只要SQL程式碼共享就可以重用，子游標的要求的比較多，特別是當使用了繫結變數或者謂詞欄位的資料分佈傾斜的時候，很容易出現多個子遊標的情況，具體子游標不能共享的原因，可以查v，這個檢視裡的一堆欄位表明了某個特定父遊標的子游標不能共享的各種原因

2、請問一下，監測rac心跳能否用直連網線？一般你們怎麼做？

rac的心跳從原理上是可以使用直連網線的，但無論是穩定性還是傳輸速率都不能完全滿足心跳的要求，因此Oracle從9i開始，在白皮書裡明確寫了不允許使用直連線的方式，主要就是出於心跳穩定和傳輸速率考慮。其實如果心跳壓力非常小的話，用直連肯定也可以，只是用rac的大部分是核心，一般不願意去冒險。

3、能不能簡單說下 rac 的高可用和我們平時做的雙機熱備有哪些區別呀。

rac的高可用是兩節點的資料庫例項同時可用，而傳統的ha則只是在一個節點上可用例項，另一個節點的例項並沒有啟動，因此，簡單來說，rac比ha至少在高可用能力上更強（兩節點同時在用，一旦單節點故障，故障節點的會話可以無縫切換到另一可用節點，前端沒有業務中斷的感覺，當然，這個需要配置好才行），而ha一旦單節點故障，業務一定得中斷，等待另一節點例項起來之後才能連線。 同時，rac也能同時發揮兩臺機器的效能，而ha的一個節點完全是浪費著（有的使用者為了避免這種浪費，就把兩個庫分別在ha的兩個節點執行，讓兩節點的兩個庫互為熱備）

4、請問除了子游標以外，還有哪些因素會導致，RAC當機或者導致其不穩定。

rac不穩定的因素很多，最典型的就是心跳線不穩定或者心跳線出現資料風暴，此外，11g的DRM特性也很容易導致rac單節點當機，一般我們都會建議禁用DRM特性。此外，11g還有很多新特性都會誘發節點當機，比如我們以前還遇到過由於asm例項記憶體太小，而在rac的asm上部署的資料庫太多導致asm例項掛掉，從而導致rac庫宕掉的。原因很多了

5、能否簡單介紹下 在 oracle最佳化中對遊標的最佳化思路與RAC常用最佳化方向。

遊標的最佳化思路，最簡單也是最根本的就是在適當的場景下用繫結變數，在不該用的時候不要亂用繫結。比如，謂詞傾斜的欄位就極度不適合繫結。另外，統計資訊的準確性，尤其是傾斜欄位的統計資訊準確性也直接影響著子游標的產生。還有一些引數也要注意，特別是cursor_sharing，寧願設定成force，也儘量不要用similar，similar很容易遭遇bug，導致一堆子游標撐爆shared pool。最後就是我們那個案例中的不同版本對子游標數的限制，不能放任子游標無窮增長。
rac的最佳化牽扯麵比較多，我先零零星星寫一些吧，太多了。比如sequence，在rac下一定要開啟cache，而且不能太小，我們對於一些常用的sequence甚至建議開啟cache到500以上，決不能使用order。
再比如如果發現GC的enq特別多，那麼就要考慮做業務分割，把操作不同表的會話連線到不同的節點例項上，減少兩節點對同一張表的徵用。

6、請說一下，RAC當機的處理思路，謝謝。

對於當機，基本上都是從資料庫的alert.log看起，一般告警日誌裡都會有最後宕掉時資料庫做的事情，甚至有更為詳細的trace檔案資訊，那麼就需要根據這些資訊結合rac各程式的關係來進行分析，這個的確不是一兩句話能說的完的。總之，肯定是要看資料庫告警日誌和crs日誌的，asm的日誌有時候也要看。而導致當機的原因同樣五花八門，有些是系統原因，比如asm儲存陣列出問題、光纖鏈路不穩定、swap耗盡等等，有些是資料庫問題，比如心跳檢測超時，為了恢復出問題的節點，自動宕掉那個節點重啟，比如由於一些資料庫的bug或者異常導致Oracle的某些關鍵程式被強制殺掉之類。。。可能性非常多了

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/26916835/viewspace-2120300/，如需轉載，請註明出處，否則將追究法律責任。

相關文章