About Oracle Hanganalyze

 

1. 資料庫hang的幾種可能性

oracle死鎖或者系統負載非常高比如cpu使用或其他一些鎖等待很高都可能導致系統hang住，比如大量的DX鎖。

通常來說，我們所指的系統hang住，是指應用無響應，普通的sqlplus幾乎無法操作等等。

2. 如何進行hang分析？hang分析有哪些level？如何選擇level？

hanganalyze有如下幾種level：

  10    Dump all processes (IGN state)

   5     Level 4 + Dump all processes involved inwait chains (NLEAF state)

   4     Level3 + Dump leaf nodes (blockers) in wait chains(LEAF,LEAF_NW,IGN_DMP state)

   3     Level2 + Dump only processes thought to be in a hang (IN_HANG state)

   1-2   Only HANGANALYZE output, no process dump at all

 

從上面的資訊看,在進行hanganalyzedump時有多種級別的level可以選擇，那麼如何選擇level？
一般來講,不建議使用level 3以上的操作,因為產生的trace可能會很大,尤其是大型的OLTP系統;
另外一般資料庫hang住時可能系統壓力都巨大,所以再產生很大的trace可能導致問題更加嚴重。

從oracle9i開始hangalanyze操作提供了針對OracleRAC的支援,有如下2種方式：

 1) ALTER SESSION SET EVENTS ‘immediate trace name HANGANALYZElevel <level>’;

  2)使用oradebug命令

       ORADEBUG setmypid
       ORADEBUG setinst all
       ORADEBUG -g def hanganalyze <level>       —針對rac的用法
     對於單例項，我們通常進行如下操作即可:
       oradebug setmypid
       oradebug hanganalyze 3
   其次在做hang分析的時候,建議同時做一個systemstatedump或針對個別的process進行processstatedump,如下：

     ---systemstate dump

        oradebug  setmypid

        oradebug  unlimit

        oradebug  dump systemstate  level 2;

        oradebug  close_trace

        oradebug  tracefile_name

 

    ---processstatedump

         oradebug  setospid xxxx

         oradebug  dump processstate level 3;

         oradebug  close_trace

         oradebug  tracefile_name

我們知道當一個資料庫hang住時,最頭痛的問題是無法登陸資料，也就無法進行故障的處理,因此很多人只能透過重啟
作業系統來講解決問題，其實從Oracle 10g開始,Oracle提供了prelim的登陸方式，如下:

    sqlplus -prelim / as sysdba 

       oradebug setospid <process ID>  

       oradebug unlimit

       oradebug dump systemstate 10

退一萬步講，即使我們無法透過SQLPLUS登陸資料庫，仍然還是可以從作業系統層面入手的，即透過作業系統的命令來

對程式進行dump,例如aix環境中可以使用dbx命令來dumpprocessstate，如下：

  dbx -a PID (where PID = any oracle shadowprocess) —透過ps -ef|grep xxx檢視  

   dbx() print ksudss(10)

   …return value printed here
    dbx() detach
3. 如何解讀hang分析的trace檔案，獲取有用資訊?

 
*** ACTION NAME:() 2010-03-12 00:04:01.497
*** MODULE NAME:( (TNS V1-V3)) 2010-03-1200:04:01.497    —模組名跟v$session.module_name一樣
*** SERVICE NAME:(SYS$USERS) 2010-03-12 00:04:01.497
*** SESSION ID:(5184.45287) 2010-03-1200:04:01.497         —-sid(5184)   serial# (35287)
*** 2010-03-12 00:04:01.497
==============
HANG ANALYSIS:
==============
Found 54 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<0/5210/10419/0x99d0a88/11215038/NoWait>                 —從這裡看 session5210阻塞了54個物件
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:    —從這裡開始以下的session都是被前面的5210阻塞
<0/5210/10419/0x99d0a88/11215038/No Wait>
– <0/3994/15494/0xd9ac1b0/6574102/enq: TM – contention>
– <0/4962/58962/0xca03618/5710044/enq: DX – contention>
Other chainsfound:                                           —下面的session也是被前面所阻塞,被間接阻塞
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4001/31548/0xf9f3ab0/4980956/enq: DX – contention>
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4014/30717/0xaa27b48/7446746/gc buffer busy>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4039/42115/0xd9f5710/5595180/PX Deq: Table Q Normal>

 

Cycle 1 : <sid/sess_srno/proc_ptr/ospid/wait_event>:        —cycle通常是死鎖一般來說很有可能就是hang的根源
<980/3887/0xe4214964/24065/latch free>
– <2518/352/0xe4216560/24574/latch free>
– <55/10/0xe41236a8/13751/latch free>

如果trace中出現了Cycle，基本上Oracle就hang了。
4. 不同版本hang分析的差異？trace有何異同？

如下是oracle8~10g的hanganalyze trace資訊格式：

  Oracle 8.x :[nodenum]/sid/sess_srno/session/state/start/finish/[adjlist]/predecessor
  Oracle9i:  [nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
  Oracle10g：[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor

 

       Nodenum     –》每個session做hanganalyze生成的一個序列號
       sid                –》 SessionID
       sess_srno      –》Serial#
       ospid            –》 OS Process Id  (v$processspid)
       state            –》 State of the node
       adjlist           –》 adjacent node  (Usually represents a  blocker node) –通常是阻塞者
       predecessor –》predecessor node (Usually represents a waiter node)  –通常是被阻塞者
        cnode         –》節點號從9i開始才有

關於state有如下幾種值:

IN_HANG      –》該狀態是一個非常危險的狀態，通常表現為一個節點陷入了死迴圈或是hung。
一般來說出現這種情況，該節點的臨闢節點也是一樣的狀態即adjlist

例如：
[16]/0/17/154/0x24617be0/26800/IN_HANG/29/32/[185]/19   —從IN_HANG我們可以看出185被16阻塞
[185]/1/16/4966/0×24617270//IN_HANG/30/31/[16]/16      —
LEAF         –》通常是被認為blockers的重點物件。那麼如何去確定呢？
一般根據後面的predecesor來判斷該session是不是blocker或者是waiter。
例子：
[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
[16]/0/17/154/0x24617be0/26800/LEAF/29/30//19        –從這裡看19是waiter因此我們認為17阻塞了20
[19]/0/20/13/0×24619830/26791/NLEAF/33/34/[16]/186

 

LEAF_NW     –》跟leaf類似不過可能會佔用cpu
NLEAF       –》該狀態的session通常被認為 “stuck”session。即其他session所需要的資源正被其holding。
IGN         –》該狀態的session通常是處理IDLE狀態，除非其adjlist存在，如果是，那麼該session正在等待其他session。
IGN_DMP     –》跟IGN類似。

例子：

[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
[16]/0/17/154/0x24617be0/26800/LEAF/29/30//19
[19]/0/20/13/0×24619830/26791/NLEAF/33/34/[16]/186
[189]/1/20/36/0×24619830//IGN/95/96/[19]/none
[176]/1/7/1/0x24611d80//IGN/75/76//none

從上面看，189在等待19,19在等待16，而176是一個idlesession。

SINGLE_NODE，SINGLE_NODE_NW可以認為跟LEAF，LEAF_NW一樣，除非沒有依賴物件。

 

5. 11g中hanganalyzetrace格式的變化
我們知道從11g(應該是從11.1)開始,Oracle的trace格式相比10g而已，有很大的改變.hanganalyzetrace格式也不例外.
如下是今天一個學生提到的問題，dropuser xxxx cascade刪除使用者時hang住.透過oradebughanganalyze 3我們來
尋找問題的根本原因，首先來看一下trace的內容：

***2014-01-23 10:53:59.779

===============================================================================

HANGANALYSIS:

 instances(db_name.oracle_sid): tlgdb.tlgdb

 oradebug_node_dump_level:3

 analysisinitiated by oradebug

 osthread scheduling delay history: (sampling every 1.000000 secs)

 0.000000secs at [ 10:53:59 ]

 NOTE:scheduling delay has not been sampled for0.578092 secs    0.000000 secs from [ 10:53:55 - 10:54:00], 5 sec avg

 0.000000secs from [ 10:52:59 - 10:54:00 ], 1 min avg

 0.000000secs from [ 10:49:00 - 10:54:00 ], 5 min avg

 vktmtime drift history

===============================================================================

 

Chainsmost likely to have caused the hang:

 [a]Chain 1 Signature: 'enq: TX - row lock contention'(cycle)

 Chain1 Signature Hash: 0xe6386940

 

===============================================================================

Cycles:

 

-------------------------------------------------------------------------------

Chain1:

-------------------------------------------------------------------------------

 Oraclesession identified by:

 {

 instance:1 (tlgdb.tlgdb)

 osid: 14027

 processid: 19, oracle@sinosoft19 (TNS V1-V3)

 sessionid: 191

 sessionserial #: 3

 }

 iswaiting for'enq: TX - row lock contention'with wait info:

 {

 p1:'name|mode'=0x54580004

 p2:'usn<<16 | slot'=0x90008

 p3:'sequence'=0x2e03

 timein wait: 0.760805 sec

 timeoutafter: never

 waitid: 3836

 blocking:0 sessions

 currentsql: <none: error encountered - unable to get kgl lock no-wait>

 shortstack:ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+163<-ksqcmi()+2848<-ksqgtlctx()+3501<-ksqgelctx()+557<-ktuGetTxForXid()+131<-ktcwit1()+336<-ktbgtl0()+1142<-kdiins0()+44906<-kdiinsp()+91<-kauxsin()+1784<-qesltcLoadIndexList()+922<-qesltcLoadIndexes()+55<-qerltcNoKdtBufferedInsRowCBK()+374<-qerltcSingleRowLoad()+279<-qerltcFetch()+380<-insexe()+682<-opiexe()+5632<-opipls()+2164<-opiodr()+917<-rpidrus()+211<-skgmstack()+148<-rp

 waithistory:

 *time between current wait andwait #1: 0.002079sec

 1.      event: 'utl_file I/O'

 timewaited: 0.000011 sec

 waitid: 3835            p1:''=0x3

 *time between wait #1 and#2: 0.000005 sec

 2.      event: 'utl_file I/O'

 timewaited: 0.000000 sec

 waitid: 3834            p1:''=0x1

 *time between wait #2 and#3: 0.000003 sec

 3.      event: 'utl_file I/O'

 timewaited: 0.000001 sec

 waitid: 3833            p1:''=0x1

 }

 andis blocked by the session at the start of the chain.

 

Chain1 Signature: 'enq: TX - row lock contention'(cycle)

Chain1 Signature Hash: 0xe6386940

-------------------------------------------------------------------------------

 

===============================================================================

Extrainformation that will be dumped at higher levels:

[level 3] :   1 node dumps -- [UNDEF] [IN_HANG]

 

Stateof ALL nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):

[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]

 

***2014-01-23 10:53:59.788

===============================================================================

ENDOF HANG ANALYSIS

===============================================================================

 

***2014-01-23 10:53:59.788

===============================================================================

HANGANALYSIS DUMPS:

 oradebug_node_dump_level:3

===============================================================================

 

Stateof LOCAL nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):

[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]

 

Dumpingcall stack forprocess with ospid 14027

Dumpingcall stack forprocess with ospid 14027

Dumpingdetailed process information (fixed sga, context, etc.) forospid 14027

 dumplocation: /u01/app/oracle/diag/rdbms/tlgdb/tlgdb/trace/tlgdb_ora_14027.trc

 

***2014-01-23 10:54:01.005

===============================================================================

HANGANALYSIS DUMPS: END

===============================================================================

 

大家可以看到trace的內容跟10g版本相比，變化比較大，其實這看起來更容易一些了，只是我們還不太習慣而已。
當然，重點是這一段內容：
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]

我們將上述內容進行分解:
nodenum：    190 表示sid
cnode:            1   表示資料庫節點編號
sid:                 191 表示sid
0x1eb8ac1b0:  3   表示serial#號
session:          0x1eb8ac1b0  表示該Session的saddr地址
ospid:            14027       表示該session的作業系統程式編號
state:             IN_HANG     表示該session的狀態
adjlist:            190         表示blocker的sid值

當我們將上述內容分解之後，你會發現,之所以dropuser沒反應，是因為被sid190所阻塞了，那麼我們最後來看一下
sid=190 是什麼程式：

SYS@tlgdb> select p.SPID from v$session s,v$process p where s.PADDR=p.ADDR and s.SID=190;

 

SPID

------------------------

14014

 

[oracle@sinosoft19 trace]$ ps -ef | grep 14014

oracle   14014     1 0 10:44 ?        00:00:00 ora_mmon_tlgdb

oracle  14682 14251  0 11:12 pts/0    00:00:00 grep 14014

很顯然,mmon程式為非核心程式,我們可以直接kill掉。當然最後kill mmon程式之後dropuser很快完成。