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 in wait chains (NLEAF state)
4      Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state)
3      Level 2 + Dump only processes thought to be in a hang (IN_HANG state)
1-2    Only HANGANALYZE output, no process dump at all

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

從oracle 9i開始hangalanyze 操作提供了針對Oracle RAC的支援,有如下2種方式：
1) ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level 3';

2) 使用oradebug 命令 -- —針對rac的用法
ORADEBUG setmypid
oradebug unlimit
ORADEBUG setinst all
ORADEBUG -g def hanganalyze 3
oradebug close_trace
oradebug tracefile_name

3) 對於單例項，我們通常進行如下操作即可:
oradebug setmypid
oradebug unlimit
oradebug hanganalyze 3
oradebug close_trace
oradebug tracefile_name

其次在做hang分析的時候,建議同時做一個systemstate dump或針對個別的process進行processstate dump,如下：

---systemstate dump
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 2;
oradebug close_trace
oradebug tracefile_name

---processstate dump
ospid指的是v$process.spid或os層的pid,而setorapid，指的是v$process.pid
oradebug setospid xxxx
oradebug dump processstate 3;
oradebug close_trace
oradebug tracefile_name

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

sqlplus -prelim / as sysdba
oradebug setospid
oradebug unlimit
oradebug dump systemstate 10

退一萬步講，即使我們無法透過SQLPLUS登陸資料庫，仍然還是可以從作業系統層面入手的，即透過作業系統的命令來
對程式進行dump,例如aix環境中可以使用dbx命令來dump processstate，如下：

dbx -a PID (where PID = any oracle shadow process)       —透過ps -ef|grep xxx檢視
dbx() print ksudss(10)
…return value printed here
dbx() detach

---dump 整個作業系統的狀態
---systemstate dump
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 2;
oradebug -g def dump systemstate 10 --RAC環境
oradebug close_trace
oradebug tracefile_name

--根據作業系統程式追蹤
---processstate dump
oradebug setospid xxxx
或者ORACLE SID，它們是一樣的：
oradebug setorapid 18 --根據Oracle ID
oradebug dump processstate 3;
oradebug close_trace

oradebug trace file_name

--獲取某程式的狀態資訊
oradebug setospid 22180
oradebug dump processstate 10
oradebug tracefile_name

--獲取程式錯誤資訊狀態
oradebug setospid 22180
oradebug dump errorstack 3
--根據要update語句或者sid 找到要跟蹤的程式，例如存在鎖的情況，可以根據阻塞的sql來生成spid
select p.spid
from v$session s,v$process p,v$sqlarea c
where s.username is not null and s.PADDR=p.ADDR and s.sql_id=c.sql_id
and s.sql_fulltext like'%UPDATE t_config_info%'
SPID

再在另一個會話中執行下面的語句
SQL> oradebug setospid SPID
SQL> oradebug unlimit
SQL> oradebug dump processstate 10
SQL> oradebug tracefile_name

---檢視oradebug 的幫助
SQL> oradebug help
SQL> oradebug dumplist

3. 如何解讀hang分析的trace檔案，獲取有用資訊'
*** ACTION NAME:() 2010-03-12 00:04:01.497
*** MODULE NAME:(sqlplus@S7_C_YZ_YZSJK (TNS V1-V3)) 2010-03-12 00:04:01.497    —模組名跟v$session.module_name一樣
*** SERVICE NAME:(SYS$USERS) 2010-03-12 00:04:01.497
*** SESSION ID:(5184.45287) 2010-03-12 00:04:01.497         —-sid (5184)   serial# (35287)
*** 2010-03-12 00:04:01.497
==============
HANG ANALYSIS:
==============
Found 54 objects waiting for
<0/5210/10419/0x99d0a88/11215038/No Wait>                  —從這裡看 session 5210 阻塞了54個物件
Open chains found:
Chain 1 : :    —從這裡開始以下的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 chains found:                                            —下面的session也是被前面所阻塞,被間接阻塞
Chain 2 : :
<0/4001/31548/0xf9f3ab0/4980956/enq: DX – contention>
Chain 3 : :
<0/4014/30717/0xaa27b48/7446746/gc buffer busy>
Chain 4 : :
<0/4039/42115/0xd9f5710/5595180/PX Deq: Table Q Normal>

Cycle 1 : :        —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         –》 Session ID
sess_srno   –》 Serial#
ospid       –》 OS Process Id (v$process spid)
state       –》 State of the node
adjlist     –》 adjacent node   (Usually represents a blocker node) –通常是阻塞者，臨近的node(通常代表一個blocker node)
predecessor –》 predecessor node (Usually represents a waiter node) –通常是被阻塞者，是Predecessor node ,通常代表一個 waiter node
cnode       –》節點號從9i開始才有

關於state 有如下幾種值:
State有如下幾種狀態：
       （1）IN_HANG：如果Session處於這種狀態，表示Session遇到deadlock或者處於hung狀態，通常還有其他node（blocker）也處於該狀態。
       （2）LEAF/LEAF_NW：這些Session通常是“blocker”或者是等待某些資源的“slow” node，透過欄位“predecessor” 可以很容易標識出這些node。
       （3）NLEAF：這些Session通常被認為是“stuck”會話，意味著這些Session在等待某些Session的資源。透過欄位“adjlist”可以很容易的定義該程式的blocker。
       （4）IGN/IGN_DMP：這些Session通常是IDLE Session。

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是一個idle session。
SINGLE_NODE，SINGLE_NODE_NW 可以認為跟LEAF，LEAF_NW一樣，除非沒有依賴物件。

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


*** 2014-01-23 10:53:59.779
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): tlgdb.tlgdb
oradebug_node_dump_level: 3
analysis initiated by oradebug
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 10:53:59 ]
NOTE: scheduling delay has not been sampled for 0.578092 secs    0.000000 secs from [ 10:53:55 - 10:54:00 ], 5 sec avg
0.000000 secs from [ 10:52:59 - 10:54:00 ], 1 min avg
0.000000 secs from [ 10:49:00 - 10:54:00 ], 5 min avg
vktm time drift history
===============================================================================

Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'enq: TX - row lock contention' (cycle)
Chain 1 Signature Hash: 0xe6386940

===============================================================================
Cycles:

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (tlgdb.tlgdb)
os id: 14027
process id: 19, oracle@sinosoft19 (TNS V1-V3)
session id: 191
session serial #: 3
}
is waiting for 'enq: TX - row lock contention' with wait info:
{
p1: 'name|mode'=0x54580004
p2: 'usn<<16 | slot'=0x90008
p3: 'sequence'=0x2e03
time in wait: 0.760805 sec
timeout after: never
wait id: 3836
blocking: 0 sessions
current sql:
short stack: 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
wait history:
* time between current wait and wait #1: 0.002079 sec
1.       event: 'utl_file I/O'
time waited: 0.000011 sec
wait id: 3835            p1: ''=0x3
* time between wait #1 and #2: 0.000005 sec
2.       event: 'utl_file I/O'
time waited: 0.000000 sec
wait id: 3834            p1: ''=0x1
* time between wait #2 and #3: 0.000003 sec
3.       event: 'utl_file I/O'
time waited: 0.000001 sec
wait id: 3833            p1: ''=0x1
}
and is blocked by the session at the start of the chain.

Chain 1 Signature: 'enq: TX - row lock contention' (cycle)
Chain 1 Signature Hash: 0xe6386940
-------------------------------------------------------------------------------

===============================================================================
Extra information that will be dumped at higher levels:
[level 3] :   1 node dumps -- [UNDEF] [IN_HANG]

State of 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
===============================================================================
END OF HANG ANALYSIS
===============================================================================

*** 2014-01-23 10:53:59.788
===============================================================================
HANG ANALYSIS DUMPS:
oradebug_node_dump_level: 3
===============================================================================

State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]

Dumping call stack for process with ospid 14027
Dumping call stack for process with ospid 14027
Dumping detailed process information (fixed sga, context, etc.) for ospid 14027
dump location: /u01/app/oracle/diag/rdbms/tlgdb/tlgdb/trace/tlgdb_ora_14027.trc

*** 2014-01-23 10:54:01.005
===============================================================================
HANG ANALYSIS 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值

當我們將上述內容分解之後，你會發現,之所以drop user沒反應，是因為被sid 190所阻塞了，那麼我們最後來看一下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程式之後drop user很快完

Oracle hanganalyze

相關文章