oracle中hanganalyze怎么用

這篇文章給大家分享的是有關oracle中hanganalyze怎么用的內容。小編覺得挺實用的，因此分享給大家做個參考，一起跟隨小編過來看看吧。

hanganalyze有兩種使用方法：
a.alter session set events 'immediate trace name hanganalyze level <level>';
會話級別，單實例和rac都可以使用。
b.--for 單實例
oradebug hanganalyze <level>
 
--for RAC
oradebug setmypid  --跟蹤當前會話
oradebug setinst all  --rac環境
oradebug -g def hanganalyze <level>
oradebug unlimit   --取消trace文件大小限制     
oradebug tracefile_name  --查看trace文件名及位置

建議oradebug hanganalyze這一條命令多執行幾次，這樣可以比較進程的變化情況，查看是真的hang了，還是很慢
--------------------------------------------
此外oredebug工具常見的用處如下：
oradebug setospid  --跟蹤系統進程
oradebug setorapid  --跟蹤ORACLE進程
-------------------------------------------

level等級和概念：
1-2:只有hanganalyze輸出，不dump任何進程
3：level2+dump出在in_hang狀態的進程
4：level3+dump出在等待鏈里面的blockers(狀態為leaf/leaf_nw/ign_dmp)
5：level4+dump出所有在等待鏈中的進程（狀態為nleaf）
Oracle官方建議不要超過level 3。level 3 對于分析問題足夠了。超過level 3會給系統帶來額外負擔。


了解了用法以后，我用library cache lock,library cache pin以及TX鎖通過上面的方法得到一個trace文件，通過trace文件分析問題以及順便解釋一下如何讀懂這個trace文件。
首先產生一個TX鎖：
第一個session：
02:05:40 SQL> select sid,serial# from v$session where sid=(select userenv('SID') from dual);

       SID    SERIAL#
---------- ----------
        32      45444

1 row selected.
02:05:55 SQL> create table t1 (id int);

Table created.
02:07:20 SQL> insert into t1 values(1);

1 row created.
02:07:36 SQL> commit;

Commit complete.
02:07:39 SQL> update t1 set id=2 where id=1;
1 row updated.
第二個session去更新同一行，hang住：
02:05:51 SQL> select sid,serial# from v$session where sid=(select userenv('SID') from dual);

       SID    SERIAL#
---------- ----------
        40      17698

1 row selected.

Elapsed: 00:00:00.00
02:06:07 SQL> update t1 set id=3 where id=1;

此時產生的等待事件：
   INST_ID     EVENT# EVENT                                                              COUNT(*)
---------- ---------- ---------------------------------------------------------------- ----------
         1        341 SQL*Net message to client                                                 1
         1        237 enq: TX - row lock contention                                             1

下面模擬library cache pin的產生：
建立兩個存儲過程：
create or replace procedure aproc
is
begin
    null;
end;
/


create or replace procedure bproc
is
begin
    aproc;
    dbms_lock.sleep(3000);
end;
/

第三個session：
02:06:13 SQL> select sid,serial# from v$session where sid=(select userenv('SID') from dual);

       SID    SERIAL#
---------- ----------
         1         18

1 row selected.

執行存儲過程：
exec bproc;

第四個session，編譯aproc，hang住：
02:06:24 SQL> select sid,serial# from v$session where sid=(select userenv('SID') from dual);

       SID    SERIAL#
---------- ----------
        17         24

1 row selected.

Elapsed: 00:00:00.00
02:06:26 SQL> alter procedure aproc compile;

此時產生了等待事件：
   INST_ID     EVENT# EVENT                                                              COUNT(*)
---------- ---------- ---------------------------------------------------------------- ----------
         1        237 enq: TX - row lock contention                                             1
         1        341 SQL*Net message to client                                                 1
         1        280 library cache pin                                                         1

第五個session執行aproc：
02:06:51 SQL> select sid,serial# from v$session where sid=(select userenv('SID') from dual);

       SID    SERIAL#
---------- ----------
        44         48

1 row selected.

02:39:45 SQL> alter procedure aproc compile;

這個時候產生了library cache lock
   INST_ID     EVENT# EVENT                                                              COUNT(*)
---------- ---------- ---------------------------------------------------------------- ----------
         1        237 enq: TX - row lock contention                                             1
         1        341 SQL*Net message to client                                                 1
         1        281 library cache lock                                                        1
         1        280 library cache pin                                                         1
這里大概講一下pin和lock的oracle內部的過程。
比如會話1執行了bproc，會話2執行了編譯aproc。此時，會話1持有了bproc和aproc的共享型（share）pin，aproc和bproc的lock未被持有；會話2編譯時，需要獲得aproc的獨占型（exclusive）pin，因為lock的優先級比pin高，所以獲得pin之前要先獲得aproc的handle的獨占型lock，這個過程沒有問題，但是在獲得aproc獨占型pin的時候，會被會話1的共享型pin阻塞。此時aproc的獨占型lock被會話2持有，共享型pin被會話1持有；bproc的共享型pin被會話1持有，bproc的獨占型lock被會話2持有。
會話1：aproc共享型pin，bproc共享型pin
會話2：aproc獨占型lock，等待aproc獨占pin（被會話1的aproc共享型pin阻塞）
這個時候如果session3再去編譯aproc，會話3先需要獲得aproc的獨占型lock，后獲得獨占型pin，獲得lock時會被會話2持有的aproc獨占型lock阻塞，產生library cache lock等待；
如果會話3去編譯bproc，會話3需要先獲得bproc的獨占型lock，然后獲得獨占型pin，lock獲得沒問題，但是在獲得獨占型pin的時候會被會話1持有bproc的共享型pin阻塞，差生library cache pin等待；
如果會話3去運行aproc，需要獲得aproc共享型的lock，但是會被會話2持有的aproc獨占型lock阻塞，從而產生過library cache lock等待。
如果會話3去運行bproc，需要獲得bproc和aproc共享型pin，aproc共享型pin的獲得需要排隊，而且排在會話2后面，bproc共享型pin會被會話1持有的bproc獨占型pin阻塞，從而產生library cache pin等待。這時如果殺掉會話1，aproc的獨占型pin會被會話2獲得，會話3還是要等待會話2。    
        
實驗驗證，完全正確！
當然以上是我自己對pin和lock的理解，如果有異議，歡迎留言。    

-------------------------------------------------------------
library cache lock和library cache pin的作用：
Oracle利用Library cache lock和Library cache pin來實現并發控制，Library cache lock是在handle上獲取的，而Library cache pin則是在data heap上獲取。訪問對象時，首先必須獲取handle上的lock，然后將訪問的數據pin在內存中。lock的作用是控制進程間的并發訪問，而pin的作用是保證數據一致性，防止數據在訪問時被交換出去
參考：http://blog.csdn.net/tianlesoftware/article/details/6641440
----------------------------------------------------------------    
        
        
現在我們總結一下阻塞情況：
(32.45444)阻塞(40.17698),(40.17698)上產生TX鎖。
(1.18)阻塞(17.24)阻塞(44.48)，第一個阻塞產生pin，第二個阻塞產生lock。


   
下面收集system hanganalyze的trace file；
順便也收集一下system statedump;

system hanganalyze:
SQL> oradebug hanganalyze 3;
Hang Analysis in /tpsys/app/oracle/diag/rdbms/ogg1/ogg1/trace/ogg1_ora_22133.trc

system statedump:
SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug dump systemstate 266
Statement processed.
SQL> oradebug dump systemstate 266
Statement processed.
SQL> oradebug tracefile_name
/tpsys/app/oracle/diag/rdbms/ogg1/ogg1/trace/ogg1_ora_22313.trc


hanganalyze產生的trace文件還是比較容易讀懂的，前面都是一些主機和庫的信息，我這里忽略了。
這一部分羅列了最有可能導致system hang的chains，發現有兩條；當trace文件很多的時候，可以搜索關鍵字Signature:
more ogg1_ora_22133.trc|grep Signature

Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
     Chain 1 Signature Hash: 0x38c48850
 [b] Chain 2 Signature: 'PL/SQL lock timer'<='library cache pin'<='library cache lock'
     Chain 2 Signature Hash: 0x38f0a7dd

下面詳細解釋其中一條阻塞鏈：
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (ogg1.ogg1)
                   os id: 17826
              process id: 33, oracle@oggtest1 (TNS V1-V3)
              session id: 44
        session serial #: 48
    }
    is waiting for 'library cache lock' with wait info:   -----會話44在經歷等待，等待信息如下：
    {
                      p1: 'handle address'=0xaa5ad9d8
                      p2: 'lock address'=0xaa605b38
                      p3: '100*mode+namespace'=0x12c3700010003
            time in wait: 3 min 2 sec
           timeout after: never
                 wait id: 45
                blocking: 0 sessions
             current sql: alter procedure aproc compile
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+1
0<-skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+162<-__PGOSF85_ksfwaitctx()+14<-kglLockWait()+867<-kgllkal()+955<-k
glLock()+989<-kglget()+323<-kkdllk0()+431<-kkdlGetCodeObject()+307<-kkpalt()+353<-opiexe()+14929<-opiosq0()+3942<-kp
ooprx()+295<-kpoal8()+779<-opiodr()+1149<-ttcpip()+1251<-opitsk()+1633<-opiino()+958<-opiodr()+1149<-opidrv()+570<-s
ou2o()+103<-opimai_real()+133<-ssthrdmain()+214<-main()+201<-__libc_start_main()+
            wait history:                              ----------會話44曾經經歷過的等待事件，但是不在阻塞鏈中。
              * time between current wait and wait #1: 0.007729 sec
              1.       event: 'asynch descriptor resize'
                 time waited: 0.000017 sec
                     wait id: 44              p1: 'outstanding #aio'=0x0
                                              p2: 'current aio limit'=0x82
                                              p3: 'new aio limit'=0x92
              * time between wait #1 and #2: 0.001617 sec
              2.       event: 'SQL*Net message from client'
                 time waited: 21.388190 sec
                     wait id: 43              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000012 sec
              3.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 42              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
    }
    and is blocked by                      --------阻塞會話44的會話信息如下：
 => Oracle session identified by:
    {
                instance: 1 (ogg1.ogg1)
                   os id: 17748
              process id: 32, oracle@oggtest1 (TNS V1-V3)
              session id: 17
        session serial #: 24
    }
    which is waiting for 'library cache pin' with wait info:      -----會話17阻塞了會話44，但是同時會話17也被其他會話阻塞
    {                                                              -----阻塞信息如下：
                      p1: 'handle address'=0xaa5ad9d8
                      p2: 'pin address'=0xaa5f2fd0
                      p3: '100*mode+namespace'=0x12c3700010003
            time in wait: 6 min 25 sec
           timeout after: 8 min 34 sec
                 wait id: 30
                blocking: 1 session
             current sql: alter procedure aproc compile
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+1
0<-skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+162<-__PGOSF85_ksfwaitctx()+14<-kglpnal()+1882<-kglpin()+978<-kkdll
k0()+967<-kkdlGetCodeObject()+307<-kkpalt()+353<-opiexe()+14929<-opiosq0()+3942<-kpooprx()+295<-kpoal8()+779<-opiodr
()+1149<-ttcpip()+1251<-opitsk()+1633<-opiino()+958<-opiodr()+1149<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ss
thrdmain()+214<-main()+201<-__libc_start_main()+253<-_start()+36
            wait history:                              ----------會話17曾經經歷過的等待事件，但是不在阻塞鏈中。
              * time between current wait and wait #1: 0.009959 sec
              1.       event: 'Disk file operations I/O'
                 time waited: 0.000028 sec
                     wait id: 29              p1: 'FileOperation'=0x2
                                              p2: 'fileno'=0xc9
                                              p3: 'filetype'=0x2
              * time between wait #1 and #2: 0.002386 sec
              2.       event: 'asynch descriptor resize'
                 time waited: 0.000003 sec
                     wait id: 28              p1: 'outstanding #aio'=0x0
                                              p2: 'current aio limit'=0x80
                                              p3: 'new aio limit'=0x82
              * time between wait #2 and #3: 0.008495 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 30 min 18 sec
                     wait id: 27              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
    }
    and is blocked by                        -------阻塞會話17的會話信息如下：
 => Oracle session identified by:
    {
                instance: 1 (ogg1.ogg1)
                   os id: 6780
              process id: 19, oracle@oggtest1 (TNS V1-V3)
              session id: 1
        session serial #: 18
    }
    which is waiting for 'PL/SQL lock timer' with wait info:  ----會話1正在經歷等待，等待信息如下：      
    {
                      p1: 'duration'=0x493e0
            time in wait: 9 min 58 sec
           timeout after: 40 min 1 sec
                 wait id: 135
                blocking: 2 sessions
             current sql: BEGIN bproc; END;
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+1
0<-skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+162<-kslwait()+141<-psdwat()+112<-pevm_icd_call_common()+421<-pfrin
str_ICAL()+169<-pfrrun_no_tool()+63<-pfrrun()+1030<-plsql_run()+774<-peicnt()+301<-kkxexe()+525<-opiexe()+14801<-kpo
al8()+2288<-opiodr()+1149<-ttcpip()+1251<-opitsk()+1633<-opiino()+958<-opiodr()+1149<-opidrv()+570<-sou2o()+103<-opi
mai_real()+133<-ssthrdmain()+214<-main()+201<-__libc_start_main()+253<-_start()+3
            wait history:                                      -------會話1曾經經歷過的等待事件，但是不在阻塞鏈中
              * time between current wait and wait #1: 0.000952 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 17.746952 sec
                     wait id: 134             p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000015 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000000 sec
                     wait id: 133             p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000002 sec
              3.       event: 'SQL*Net break/reset to client'
                 time waited: 0.000088 sec
                     wait id: 132             p1: 'driver id'=0x62657100
                                              p2: 'break?'=0x0
    }
 ---------到此為止，發現會話1沒有被其他會話阻塞了，說明這條阻塞鏈的源頭已經找到了，就是會話1.與我們之前已知的阻塞情形是完全吻合的。會話1在等待的'PL/SQL lock timer'就是存儲過程dbms_lock.sleep造成的。
Chain 2 Signature: 'PL/SQL lock timer'<='library cache pin'<='library cache lock'
Chain 2 Signature Hash: 0x38f0a7dd
-------------------------------------------------------------------------------

簡化一下就是：
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                被阻塞會話信息
    }
    is waiting for 'library cache lock<等待事件名稱>' with wait info:
    {
                      等待事件的信息
            wait history:
              該被阻塞會話歷史等待事件，這里與阻塞鏈沒關系，只是羅列出來供我們分析關聯性。
    }
    and is blocked by                 ----阻塞源信息：
 => Oracle session identified by:    
    {
                阻塞會話信息
    }
    which is waiting for 'library cache pin<等待事件名稱>' with wait info:   ----該阻塞會話同時也被其他會話阻塞，也在等待
    {
                      該會話經歷等待的事件的詳細情況
            wait history:
              該會話還在經歷其他不在阻塞鏈中的等待事件
    }
    and is blocked by                 -----上面會話的阻塞源
 => Oracle session identified by:
    {
                阻塞源信息
    }
    which is waiting for 'PL/SQL lock timer' with wait info:
    {
                      阻塞事件詳情
            wait history:
              該會話還在經歷其他不在阻塞鏈中的等待事件
    }
 
Chain 2 Signature: 'PL/SQL lock timer'<='library cache pin'<='library cache lock'   -----阻塞鏈
Chain 2 Signature Hash: 0x38f0a7dd
-------------------------------------------------------------------------------
我們可以用下面nl ogg1_ora_22133_hang.trc |grep "which is waiting for"    
    88      which is waiting for 'SQL*Net message from client' with wait info:
   169      which is waiting for 'library cache pin' with wait info:
   208      which is waiting for 'PL/SQL lock timer' with wait info:
然后根據行數去找到大概位置。
比如88和169,208相隔比較遠，猜測可能是另外一條阻塞鏈，這里88應該是TX那條阻塞鏈。

下面看一下阻塞鏈的簡化信息。我自己是把這部分信息看做上面阻塞鏈只保留了會話基本信息以后的阻塞關系。
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[0]/1/1/18/0xa8bc3930/6780/LEAF/
[16]/1/17/24/0xa8b95230/17748/NLEAF/[0]
[31]/1/32/45444/0xa8b699a0/17703/LEAF/
[39]/1/40/17698/0xa8b52620/17704/NLEAF/[31]
[43]/1/44/48/0xa8b46c60/17826/NLEAF/[16]

每一行從后往前讀的時候
把leaf看做被阻塞
nleaf看做阻塞。
先找到leaf，leaf一般是阻塞的源頭。這里[0]是一個源頭，然后再其他行結尾找[0]，但是每一行倒著讀的時候leaf和nleaf的含義也要相反。
[0](即會話1) nleaf（阻塞） [16](即會話17)：0阻塞16；
找到[16]那一行，同理：
16阻塞了43
沒有找到[43]那一行，說明[43]是阻塞鏈的末端。
綜上：會話1 blocking 會話17 blocking 會話44；
如果要殺的話，先殺1，在殺17。

還有一個leaf：相關兩行：
[31]/1/32/45444/0xa8b699a0/17703/LEAF/
[39]/1/40/17698/0xa8b52620/17704/NLEAF/[31]
會話32阻塞了會話40，即我們之前產生的TX鎖。

完全正確！

下面是一些解釋：
[nodenum]：阻塞鏈中session的序列號
cnode：節點number，針對rac
sid:session sid
sess_srno:session serial#
session:會話地址
ospid:操作系統進程id
state:節點狀態
[adjlist]:blocker node session nodenum
predecessor：waiter node session nodenum

--------------------------------------------------------------------------------------------------
state：
IN_HANG ：該狀態是一個非常危險的狀態，通常表現該會話陷入了死循環或掛起(hang)。
          一般來說出現這種情況，該節點的臨近節點(adjlist)也是一樣的狀態.adjlist 其實就是表示session id.
LEAF    ：通常是被認為blockers的重點對象。可以根據后面的predecesor來判斷該session是不是blocker或者是waiter。
LEAF_NW ：跟leaf類似 不過可能會占用cpu
NLEAF   ：該狀態的session通常被認為 “stuck” session。即其他session所需要的資源正被其holding。
IGN     ：該狀態的session通常是處理IDLE狀態，除非其adjlist存在，如果是，那么該session正在等待其他session。
IGN_DMP ：跟IGN類似。
SINGLE_NODE，SINGLE_NODE_NW 可以認為跟LEAF，LEAF_NW類似。
參考：http://blog.csdn.net/xujinyang/article/details/6858086
        IGN     ignore
        LEAF    A waiting leaf node
        LEAF_NW A running (using CPU?) leaf node
        NLEAF   An element in a chain but not at the end (not a leaf)
參考：EVENT: HANGANALYZE - Reference Note (文檔 ID 130874.1)
-----------------------------------------------------------------------------------------------------

trace文件中還有一個non-intersecting chains，相對應的是intersecting chains，區別：
從字面意思來看，intersect是交叉，即兩條阻塞鏈中的會話都不相同即為non-intersecting chains；如果兩條chains中有相同的會話，比如類似‘X’有一個交叉點會話，即為intersecting chains。

感謝各位的閱讀！關于“oracle中hanganalyze怎么用”這篇文章就分享到這里了，希望以上內容可以對大家有一定的幫助，讓大家可以學到更多知識，如果覺得文章不錯，可以把它分享出去讓更多的人看到吧！