基於oracle 10.2.0.1 rac使用oradebug dump hanganalyze 分析oracle hang系列四

背景

   發現oracle 10.2.0.1 rac的SQL查詢也HANG住了，藉此用下hanganalyze，練練手，但發現基於RAC的HANGANALYZE與單例項的TRACE FILE區別相當大，一時也抓不到頭緒，
既然如此，學習下基於RAC的HANAANALYZE的產生TRACE FILE的格式及內容構成。   

結論

1,基於rac環境下 
預設的RAC下的ORADEBUG DUMP HANGANALYZE 3與ORADEBUG SETINST ALL以及ORADEBUG DUMP HANGANALYZE 3產生的TRACE FILE內容相同


2,trace file共計4個部分
  2.1，第一部分
  Open chains found:  --這是第一部分，這個部分可能有值，也可能無值，經過對比，發現如果DB HANG，此部分會有值


  2.2, 第二部分
  Other chains found: --這是第二部分
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/137/1/0x83a64388/7504/Streams AQ: waiting for time man>


  2.3,第三部分
   Extra information that will be dumped at higher levels:  ---如果DUMP級別越高，獲取的資訊越多，下為具體的講解
[level  5] :   6 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP] 
[level 10] :  21 node dumps -- [IGN] 
   
  2.4，第四部分
  State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none  --可見predecessor全為none
[137]/1/138/2/0x83b563a8/7377/SINGLE_NODE/5/6//none
[139]/1/140/5/0x83b58c18/7137/SINGLE_NODE/7/8//none  --可見adjlist為


3，trace file中一些標識的含義：
    cnode即生成hanganalyze的RAC節點編號（節點編號從0開始，依次遞增），這個其實對於分析沒有什麼實質的意義，不過可以從這個看出，TRACEFILE是在哪個RAC節點生成的
    start及finish感覺好像是2個連續的數字，並且採用迴環式前進編號，即1，2為對應一條記錄，然後3，4對應下面的記錄，依次類推
    sess_srno為session為v$session.saddr


4,同時從另一個RAC節點，可見在持鎖會話的告警日誌會提示持鎖程式的資訊以及生成TRACE FILE
Tue Nov 10 09:00:06 2015
GES: Potential blocker (pid=3541) on resource TX-0xa0007-0x87;
 enqueue info in file /u01/app/oracle/admin/jingfa/bdump/jingfa1_lmd0_15271.trc and DIAG trace file
   引申下，即發生鎖問題，可以從告警日誌找到相關的線索，進一步分析

分析方法

   1,以模擬環境生成trace file,以理解其內容，爾後反推和生產環境進行比對參考學習
   2,對比性學習，即如果對某個值不同，以正向測試下，再以反向測試下，可以瞭解此值或標識的含義
         

測試

--node1


SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);


       SID    SERIAL# SADDR
---------- ---------- ----------------
       153          5 0000000083B692F0


SQL> select  pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));


       PID SPID
---------- ------------
        18 3541




SQL> select * from t_lock;


         A          B
---------- ----------
         1          1
         2          2




--node2


SQL> conn tbs_zxy/system
Connected.
SQL> select sid,serial#,saddr from v$session where sid=153;


       SID    SERIAL# SADDR
---------- ---------- ----------------
       153          5 0000000083B692F0


SQL> select  pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));


       PID SPID
---------- ------------
        18 31569




--node1
SQL> update t_lock set a=11 where a=1;


1 row updated.


--node2
SQL> update t_lock set a=121 where a=1;


--hang住


---node2
--生成一個tracefile
SQL> oradebug setmypid
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name


==============
HANG ANALYSIS:
==============
Open chains found:  --這是第一部分，這個部分可能有值，也可能無值，經過對比，發現如果DB HANG，此部分會有值
Other chains found: --這是第二部分
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/137/1/0x83a64388/7504/Streams AQ: waiting for time man>
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/138/2/0x83a63ba0/7377/Streams AQ: qmn slave idle wait>
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> : --空閒等待事件不用關注
    <1/140/5/0x83a62bd0/7137/Streams AQ: qmn coordinator idle>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/148/645/0x83a60448/5400/No Wait>                       --No Wait表明當前會話不等待什麼資源，不用關注
Chain 5 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/153/5/0x83a5e4a8/31569/enq: TX - row lock contention>  ---需要關注，直接可以定位到
Chain 6 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/169/1/0x83a56e10/6621/DIAG idle wait>


如下為第三部分    
Extra information that will be dumped at higher levels:  ---如果DUMP級別越高，獲取的資訊越多，下為具體的講解
[level  5] :   6 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP] 
[level 10] :  21 node dumps -- [IGN] 
 
此為第四部分 
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none  --可見predecessor全為none
[137]/1/138/2/0x83b563a8/7377/SINGLE_NODE/5/6//none
[139]/1/140/5/0x83b58c18/7137/SINGLE_NODE/7/8//none  --可見adjlist為空
[142]/1/143/1/0x83b5c8c0/6971/IGN/9/10//none
[143]/1/144/1/0x83b5dcf8/6944/IGN/11/12//none
[144]/1/145/1/0x83b5f130/6950/IGN/13/14//none
[147]/1/148/645/0x83b62dd8/5400/SINGLE_NODE_NW/15/16//none --start及finish感覺好像是2個連續的數字，並且採用迴環式前進編號，即1，2為對應一條記錄，然後3，4對應下面的記錄，依次類推
[149]/1/150/1/0x83b65648/6710/IGN/17/18//none
[150]/1/151/1/0x83b66a80/6706/IGN/19/20//none
[152]/1/153/5/0x83b692f0/31569/SINGLE_NODE/21/22//none --等待者的資訊，session為v$session.saddr
[153]/1/154/1/0x83b6a728/6701/IGN/23/24//none
[154]/1/155/1/0x83b6bb60/6649/IGN/25/26//none
[155]/1/156/1/0x83b6cf98/6647/IGN/27/28//none
[156]/1/157/1/0x83b6e3d0/6645/IGN/29/30//none
[157]/1/158/1/0x83b6f808/6643/IGN/31/32//none
[158]/1/159/1/0x83b70c40/6641/IGN/33/34//none
[159]/1/160/1/0x83b72078/6639/IGN/35/36//none
[160]/1/161/1/0x83b734b0/6637/IGN/37/38//none
[161]/1/162/1/0x83b748e8/6635/IGN/39/40//none
[162]/1/163/1/0x83b75d20/6633/IGN/41/42//none
[164]/1/165/1/0x83b78590/6629/IGN/43/44//none
[165]/1/166/1/0x83b799c8/6627/IGN/45/46//none
[166]/1/167/1/0x83b7ae00/6625/IGN/47/48//none
[167]/1/168/1/0x83b7c238/6623/IGN/49/50//none
[168]/1/169/1/0x83b7d670/6621/SINGLE_NODE/51/52//none
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none
====================
END OF HANG ANALYSIS
====================
/u01/app/oracle/admin/jingfa/udump/jingfa2_ora_5400.trc


同時從另一個RAC節點，可見在持鎖會話的告警日誌會提示持鎖程式的資訊以及生成TRACE FILE
Tue Nov 10 09:00:06 2015
GES: Potential blocker (pid=3541) on resource TX-0xa0007-0x87;
 enqueue info in file /u01/app/oracle/admin/jingfa/bdump/jingfa1_lmd0_15271.trc and DIAG trace file


--node2
上述TRACE FILE是基於單例項模式生成TRACE FILE，我們基於RAC環境再生成下TRACE FILE，對比看內容有何區別


SQL> oradebug setinst all
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/admin/jingfa/udump/jingfa2_ora_1139.trc


經過對比，預設的RAC下的ORADEBUG DUMP HANGANALYZE 3與ORADEBUG SETINST ALL以及ORADEBUG DUMP HANGANALYZE 3產生的TRACE FILE內容相同


==============
HANG ANALYSIS:
==============
Open chains found:
Other chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/137/1/0x83a64388/7504/Streams AQ: waiting for time man>
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <1/138/2/0x83a63ba0/7377/Streams AQ: qmn slave idle wait>
中間內容略
[166]/1/167/1/0x83b7ae00/6625/IGN/47/48//none
[167]/1/168/1/0x83b7c238/6623/IGN/49/50//none
[168]/1/169/1/0x83b7d670/6621/SINGLE_NODE/51/52//none
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none
====================
END OF HANG ANALYSIS
====================


再看看下cnode的含義
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none


我們調整下在RAC2個節點阻塞者及等待者的順序


---node2
SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);


       SID    SERIAL# SADDR
---------- ---------- ----------------
       153         20 0000000083B692F0




SQL> select  pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));


       PID SPID
---------- ------------
        18 15971




 SQL> update t_lock set a=11 where a=1;


1 row updated.              


---node1


SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);


       SID    SERIAL# SADDR
---------- ---------- ----------------
       153          9 0000000083B692F0




SQL> select  pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));


       PID SPID
---------- ------------
        18 27178




SQL> update t_lock set a=123 where a=1;


hang住


--node1
生成trace file


SQL> oradebug setmypid
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/admin/jingfa/udump/jingfa1_ora_30236.trc


---可見在NODE1生成trace file,cnode為0
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[136]/0/137/6/0x83b54f70/31964/IGN/1/2//none
中間內容略
[167]/0/168/1/0x83b7c238/15267/IGN/43/44//none
[168]/0/169/1/0x83b7d670/15265/SINGLE_NODE/45/46//none
[169]/0/170/1/0x83b7eaa8/15263/IGN/47/48//none


---延續上，在node2生成TRACE FILE
---可見在NODE2生成trace file,cnode為1
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none
中間內容略
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none


可見在不同RAC節點生成hanganalyze ,其cnode對應生成hanganalyze的RAC節點編號（節點編號從0開始，依次遞增）
這個其實對於分析沒有什麼實質的意義，不過可以從這個看出，TRACEFILE是在哪個RAC節點生成的