oracledebug hanganalyze分析會話等待及儲存過程hang

wisdomone1發表於2012-12-03
測試
1,oracledebug hanganalyze普通使用者可以執行嗎
 SQL> oradebug hanganalyze
          Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_2260.trc
          SQL> conn
          已連線。
          SQL> oradebug hanganalyze
         ORA-01031: 許可權不足
        
         小結:普通使用者不能執行此命令
        
  SQL> conn as sysdba
          已連線。
          SQL> grant dba to scott;
         
          授權成功。
         
          SQL> conn
          已連線。
          SQL> oradebug hanganalyze
          ORA-01031: 許可權不足
         
          小結:dba許可權不能執行此命令
          綜述:僅sysdba才可以執行此命令
2,使用方法
  1,分別開啟兩個scott使用者連線的session,sid分別為:72,135
      72為持鎖會話,135會等待鎖會話
    2,以sysdba執行如下命令
        SQL> conn as sysdba
        已連線。
        SQL> oradebug hanganalyze
        Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_5372.trc
SQL>
3,如何檢視trace檔案
   如下為trace檔案內容:
 
--部分無關內容略---
 
 --如下說明hang是因為什麼原因引起,即什麼事件,很明顯是row lock contention,因為
 --72會話update dept一行記錄,而135會話也想更新dept表的同樣的記錄
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
 
===============================================================================
Non-intersecting chains:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    --等待鎖的會話
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 5568
              process id: 26, ORACLE.EXE (SHAD)
              session id: 135 --135會話等待鎖
        session serial #: 5
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006 --等待模式
                      p2: 'usn<<16 | slot'=0x8000e --等待相關資訊
                      p3: 'sequence'=0x5819
            time in wait: 16.246637 sec
           timeout after: never
                 wait id: 51
                blocking: 0 sessions
               
            --等待歷史,等3次
            wait history:
              * time between current wait and wait #1: 0.003008 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 15.462328 sec
                     wait id: 50              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000010 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000004 sec
                     wait id: 49              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000197 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.021308 sec
                     wait id: 48              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
   
    ---持鎖會話
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 1996
              process id: 25, ORACLE.EXE (SHAD)
              session id: 72 --會話72
        session serial #: 29
    }
    which is waiting for 'SQL*Net message from client' with wait info:
    {
                      p1: 'driver id'=0x54435000
                      p2: '#bytes'=0x1
            time in wait: 53.462782 sec
           timeout after: never
                 wait id: 71
                blocking: 1 session --此處也說明它是持鎖會話
            wait history:
              * time between current wait and wait #1: 0.000010 sec
              1.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 70              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000159 sec
              2.       event: 'SQL*Net message from client'
                 time waited: 0.003821 sec
                     wait id: 69              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000021 sec
              3.       event: 'SQL*Net message to client'
                 time waited: 0.000004 sec
                     wait id: 68              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
 
Chain 1 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
Chain 1 Signature Hash: 0x38c48850
-------------------------------------------------------------------------------
 
===============================================================================
--如下資訊說明:可以更為詳細trace hanganalyze檔案
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [LEAF] [LEAF_NW]
[level  5] :   1 node dumps -- [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW]
 
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[71]/1/72/29/F2601B6C/1996/LEAF/
[134]/1/135/5/F26A714C/5568/NLEAF/[71]
*** 2012-11-30 19:17:44.515
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2012-11-30 19:17:44.515
Oradebug command 'hanganalyze' console output:
Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_5372.trc
 
--如下為模擬編譯儲存過程hang的trace檔案
*** 2012-11-30 19:17:44.515
Oradebug command 'hanganalyze' console output:
Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_5372.trc
*** 2012-11-30 19:39:48.287
Processing Oradebug command 'hanganalyze'
*** 2012-11-30 19:39:48.287
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): orcl.orcl
  no oradebug node dumps
  analysis initiated by oradebug
===============================================================================
 --儲存過程編譯hang原因是等待library cache pin
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'PL/SQL lock timer'<='library cache pin'
     Chain 1 Signature Hash: 0xa7a4880c
 
===============================================================================
Non-intersecting chains:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    --同上述的trace檔案一個道理
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 5568
              process id: 26, ORACLE.EXE (SHAD)
              session id: 135
        session serial #: 5
    }
    is waiting for 'library cache pin' with wait info:
    {
                      p1: 'handle address'=0xebb45c5c
                      p2: 'pin address'=0xebd6695c
                      p3: '100*mode+namespace'=0x20a6b00010003
            time in wait: 8.797742 sec
           timeout after: 14 min 51 sec
                 wait id: 80
                blocking: 0 sessions
            wait history:
              * time between current wait and wait #1: 0.010977 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 11.784077 sec
                     wait id: 79              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000003 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 78              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000051 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.001355 sec
                     wait id: 77              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 1996
              process id: 25, ORACLE.EXE (SHAD)
              session id: 72
        session serial #: 29
    }
    which is waiting for 'PL/SQL lock timer' with wait info:
    {
                      p1: 'duration'=0x7530
            time in wait: 28.097329 sec
           timeout after: 4 min 31 sec
                 wait id: 273
                blocking: 1 session
            wait history:
              * time between current wait and wait #1: 0.003674 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 28.093404 sec
                     wait id: 272             p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000011 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000003 sec
                     wait id: 271             p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000821 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.005253 sec
                     wait id: 270             p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
 
Chain 1 Signature: 'PL/SQL lock timer'<='library cache pin'
Chain 1 Signature Hash: 0xa7a4880c

--某個session等待後臺程式事件也可以分析出來
===============================================================================
Sessions in an involuntary wait or not in a wait:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    --等待會話
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 1996
              process id: 25, ORACLE.EXE (SHAD)
              session id: 72
        session serial #: 29
    }
    is not in a wait:
    {
               last wait: 1.794896 sec ago
                blocking: 0 sessions
               
             --等待什麼事件
            wait history:
              1.       event: 'log buffer space' --等待log buffer space,
                 time waited: 0.112722 sec
                     wait id: 493            
              * time between wait #1 and #2: 0.058570 sec
              2.       event: 'log buffer space'
                 time waited: 0.554377 sec
                     wait id: 492            
              * time between wait #2 and #3: 2.730704 sec
              3.       event: 'log file switch completion'
                 time waited: 0.039726 sec
                     wait id: 491            
    }
 
Chain 1 Signature:
Chain 1 Signature Hash: 0x673a0128
-------------------------------------------------------------------------------
 
===============================================================================
Extra information that will be dumped at higher levels:
[level  5] :   1 node dumps -- [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW]
 
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[71]/1/72/29/F2601B6C/1996/SINGLE_NODE_NW/
*** 2012-11-30 19:53:05.027
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2012-11-30 19:53:05.027
Oradebug command 'hanganalyze' console output:
Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_5372.trc
*** 2012-11-30 19:54:13.215
Processing Oradebug command 'hanganalyze'
*** 2012-11-30 19:54:13.215
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): orcl.orcl
  no oradebug node dumps
  analysis initiated by oradebug
===============================================================================
 
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'log file parallel write'<='log buffer space'
     Chain 1 Signature Hash: 0x56c5cf5
 [b] Chain 2 Signature: 'control file parallel write'
     Chain 2 Signature Hash: 0xc17840d5
 
===============================================================================
Non-intersecting chains:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 1996
              process id: 25, ORACLE.EXE (SHAD)
              session id: 72
        session serial #: 29
    }
    is waiting for 'log buffer space' with wait info:
    {
            time in wait: 0.058057 sec
           timeout after: never
                 wait id: 546
                blocking: 0 sessions
            wait history:
              * time between current wait and wait #1: 0.205410 sec
              1.       event: 'log file switch completion'
                 time waited: 0.170435 sec
                     wait id: 545            
              * time between wait #1 and #2: 2.264604 sec
              2.       event: 'log buffer space'
                 time waited: 0.158046 sec
                     wait id: 544            
              * time between wait #2 and #3: 0.368460 sec
              3.       event: 'log buffer space'
                 time waited: 0.030237 sec
                     wait id: 543            
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 5544
              process id: 11, ORACLE.EXE (LGWR)
              session id: 189
        session serial #: 1
    }
    which is waiting for 'log file parallel write' with wait info:
    {
                      p1: 'files'=0x1
                      p2: 'blocks'=0x37e
                      p3: 'requests'=0x1
            time in wait: 0.219642 sec
           timeout after: never
                 wait id: 7393
                blocking: 1 session
            wait history:
              * time between current wait and wait #1: 0.043510 sec
              1.       event: 'control file sequential read'
                 time waited: 0.000368 sec
                     wait id: 7392            p1: 'file#'=0x0
                                              p2: 'block#'=0x20
                                              p3: 'blocks'=0x1
              * time between wait #1 and #2: 0.000489 sec
              2.       event: 'control file sequential read'
                 time waited: 0.000401 sec
                     wait id: 7391            p1: 'file#'=0x0
                                              p2: 'block#'=0x16
                                              p3: 'blocks'=0x1
              * time between wait #2 and #3: 0.000041 sec
              3.       event: 'control file sequential read'
                 time waited: 0.000341 sec
                     wait id: 7390            p1: 'file#'=0x0
                                              p2: 'block#'=0x1
                                              p3: 'blocks'=0x1
    }
 
Chain 1 Signature: 'log file parallel write'<='log buffer space'
Chain 1 Signature Hash: 0x56c5cf5
-------------------------------------------------------------------------------
 
===============================================================================
Sessions in an involuntary wait or not in a wait:
 
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 5548
              process id: 12, ORACLE.EXE (CKPT)
              session id: 3
        session serial #: 1
    }
    is waiting for 'control file parallel write' with wait info:
    {
                      p1: 'files'=0x2
                      p2: 'block#'=0x3
                      p3: 'requests'=0x2
            time in wait: 0.012544 sec
           timeout after: never
                 wait id: 4688
                blocking: 0 sessions
            wait history:
              * time between current wait and wait #1: 0.000196 sec
              1.       event: 'rdbms ipc message'
                 time waited: 2.995334 sec
                     wait id: 4687            p1: 'timeout'=0x12c
              * time between wait #1 and #2: 0.000014 sec
              2.       event: 'rdbms ipc message'
                 time waited: 0.000003 sec
                     wait id: 4686            p1: 'timeout'=0x12c
              * time between wait #2 and #3: 0.000036 sec
              3.       event: 'control file sequential read'
                 time waited: 0.000253 sec
                     wait id: 4685            p1: 'file#'=0x0
                                              p2: 'block#'=0x14
                                              p3: 'blocks'=0x1
    }
 
Chain 2 Signature: 'control file parallel write'
Chain 2 Signature Hash: 0xc17840d5
-------------------------------------------------------------------------------
 
===============================================================================
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [LEAF] [LEAF_NW]
[level  5] :   2 node dumps -- [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW]
 
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[2]/1/3/1/F256C9CC/5548/SINGLE_NODE/
[71]/1/72/29/F2601B6C/1996/NLEAF/[188]
[188]/1/189/1/F2764D8C/5544/LEAF/
*** 2012-11-30 19:54:13.230
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2012-11-30 19:54:13.230
Oradebug command 'hanganalyze' console output:
Hang Analysis in d:\oracle\diag\rdbms\orcl\orcl\trace\orcl_ora_5372.trc
 
4,小結:
    1,僅sysdba可執行
    2,執行命令即知道trace檔案所在路徑
    3,trace檔案結構清晰

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

相關文章