hanganalyze解決row cache lock(ZT)

lwitpub發表於2011-04-05
執行一個split分割槽的指令碼時長時間沒有響應。登入上去檢視，手工執行了split指令碼，發現確實會hang住：
SQL> ALTER TABLE A_PDA_SP_STAT SPLIT PARTITION P_MAX AT (20090609)
 INTO (PARTITION P_20090608 TABLESPACE TS_DATA_A , PARTITION P_MAX TABLESPACE TS_DATA_A)
SQL>

檢查該session的等待事件：

EVENT                                  P1         P2         P3
------------------------------ ---------- ---------- ----------
row cache lock                          8          0          5

查了網上的一些資料，說和sga的shared pool大小不足有關，或者和sequence的cache不大有關。經過分析，這2個原因應該都不是。因為1、如果是shared pool不足，這樣的現象一般是某個sql執行的比較慢，但是還是會執行完，而不是像現在這樣的掛住；2，只是執行split分割槽，並沒有和 sequence相關。

在這裡，我們用hanganalyze來進行分析。

hanganalyze用法：

(在這裡我們用oradebug來用做hanganalyze)
1.oradebug setospid
2.oradebug analyze <level>
然後觀察出來的trace檔案。

這裡的level有如下幾級：

Dump     Level Dump Contains
----------------------------------------
1-2      Only HANGANALYZE output, no process dump at all
3        Level 2 + Dump only processes thought to be in a hang (IN_HANG state)
4        Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state)
5        Level 4 + Dump all processes involved in wait chains (NLEAF state)
10       Dump all processes (IGN state)

我們現在來看看出來的trace檔案：

SQL> select spid from v$session a,v$process b where a.paddr=b.addr and a.sid=295;
SPID
------------
19237
SQL> oradebug SETOSPID 19237
Oracle pid: 235, Unix process pid: 19237, image: oracle@hl_rdb01 (TNS V1-V3)
SQL>
SQL> oradebug hanganalyze 3;
Cycle 1: (0/295)
Cycle 2: (0/254)--(0/239)
Hang Analysis in /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
SQL> !
$ more /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Dump file /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production
ORACLE_HOME = /oracle/app/oracle/product/9.2.0
System name:    HP-UX
Node name:      hl_rdb01
Release:        B.11.11
Version:        U
Machine:        9000/800
Instance name: hlreport
Redo thread mounted by this instance: 1
Oracle process number: 157
Unix process pid: 25247, image: oracle@hl_rdb01 (TNS V1-V3)
 
*** SESSION ID:(312.10459) 2009-05-20 16:21:58.423
*** 2009-05-20 16:21:58.423
==============
HANG ANALYSIS:
==============
 Cycle 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/329/43816/0x4d6b5638/23487/row cache lock>
 -- <0/254/19761/0x4d687438/23307/library cache lock>
Cycle 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/295/57125/0x4d6b8978/19237/row cache lock>
Cycle 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/295/57125/0x4d6b8978/19237/row cache lock>
Open chains found:
Other chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/312/10459/0x4d69f9b8/25247/No Wait>
Extra information that will be dumped at higher levels:
[level  3] :   4 node dumps -- [IN_HANG]
[level  5] :   1 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 10] : 223 node dumps -- [IGN]
 
State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[0]/0/1/1/0x4d7146c0/5132/IGN/1/2//none

……………………………………………………

[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
……………………………………………………

[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294

………………………………………………………………

[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253
………………………………………………………………

Dumping System_State and Fixed_SGA in process with ospid 13476
Dumping Process information for process with ospid 13476
Dumping Process information for process with ospid 23307
Dumping Process information for process with ospid 19237
Dumping Process information for process with ospid 23487

====================
END OF HANG ANALYSIS
====================
*** 2009-05-20 16:48:20.686

我們來看看([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor)部分：
nodenum是hanganalyze自己為了記錄這些會話而定製的編號，從0開始排起。
cnode是Node Id
sid是 Session ID
sess_srno是serial#
proc_ptr是Process Pointer
ospid 是OS Process ID
state 是node的狀態
adjlist是臨近的node(通常代表一個blocker node)
predecessor是Predecessor node ,通常代表一個 waiter node

state部分有幾個比較重要的狀態：
1.IN_HANG：這表示該node處於死鎖狀態，通常還有其他node（blocker）也處於該狀態
2.LEAF/LEAF_NW：該node通常是blocker。透過條目的”predecessor”列可以判斷這個node是否是blocker。LEAF說明該NODE沒有等待其他資源，而LEAF_NW則可能是沒有等待其他資源或者是在使用CPU.
3.NLEAF：通常可以看作這些會話是被阻塞的資源。發生這種情況一般說明資料庫發生效能問題而不是資料庫hang
4.IGN/IGN_DMP：這類會話通常被認為是空閒會話，除非其adjlist列裡存在node。如果是非空閒會話則說明其adjlist裡的node正在等待其他node釋放資源。
5.SINGLE_NODE/SINGLE_NODE_NW：近似於空閒會話

現在我們來看看我們的trace出來的檔案：
Cycle 1 : :
<0/329/43816/0x4d6b5638/23487/row cache lock>
— <0/254/19761/0x4d687438/23307/library cache lock>
Cycle 2 : :
<0/295/57125/0x4d6b8978/19237/row cache lock>
Cycle 3 : :
<0/295/57125/0x4d6b8978/19237/row cache lock>

cycle表示oracle內部確定的死鎖。其中我們的當前手工執行split的295程式也在裡面。
我們觀察其他的程式在做什麼，如329：

SQL> l
  1  select machine,status,program,sql_text from v$session a ,v$sqlarea b
  2* where a.sql_address=b.address and a.sid=329
SQL> /
 
MACHINE                                                          STATUS
---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
--------------------------------------------------------------------------------
hl_rdb01                                                         ACTIVE
sqlplus@hl_rdb01 (TNS V1-V3)
ALTER TABLE A_PDA_SP_STAT SPLIT PARTITION P_MAX AT (20090609)  INTO (PARTITION P
_20090608 TABLESPACE TS_DATA_A  , PARTITION P_MAX TABLESPACE TS_DATA_A)
 
SQL> select event from v$session_wait where sid=329;
 
EVENT
----------------------------------------------------------------
row cache lock

發現也是在執行split語句，但是問了同事，他已經把之前執行失敗的指令碼完全kill掉了。
估計在資料庫中程式掛死了，沒有完全的釋放。
kill掉329號程式後，發現還是掛住，所以我們繼續做hanganlyze：

==============
HANG ANALYSIS:
==============
 
Cycle 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/295/57125/0x4d6b8978/19237/row cache lock>
Cycle 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/254/19761/0x4d687438/23307/library cache lock>
 -- <0/239/57618/0x4d6b74f8/13476/row cache lock>

我們繼續把其他的程式殺掉。終於295的split執行成功。

SQL> ALTER TABLE A_PDA_SP_STAT SPLIT PARTITION P_MAX AT (20090609)
  INTO (PARTITION P_20090608 TABLESPACE TS_DATA_A  , PARTITION P_MAX TABLESPACE TS_DATA_A)
SQL> /
     
Table altered.
 
Elapsed: 00:31:03.21
SQL>

繼續執行split下一個分割槽，也很快完成。

SQL> ALTER TABLE A_PDA_SP_STAT SPLIT PARTITION P_MAX AT (20090610)
  2   INTO (PARTITION P_20090609 TABLESPACE TS_DATA_A
  3   , PARTITION P_MAX TABLESPACE TS_DATA_A);
 
Table altered.
 
Elapsed: 00:00:00.02
SQL>
至此，問題解決.

[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294
[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253
329堵塞住了254
254堵塞住了295
295堵塞住了238

殺掉的應該是329,254,295

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

相關文章