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

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很快完成。

About Oracle Hanganalyze

相關文章