hanganalyze分析會話阻塞

hanganalyze分析會話阻塞

 

 

參考文件:USING AND READING HANGANALYZE或者[ID 215858.1]

1、模擬阻塞會話
資料庫版本：
SQL> select * from v$version;

BANNER
----------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for 32-bit Windows: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production

會話1：
SQL> delete from t_lf where id=1;

已刪除 1 行。

會話2：
SQL> delete from t_lf where id=1;
會話此時hang住

2、hanganalyze分析
--sys登入
SQL> oradebug setmypid
已處理的語句
SQL> oradebug unlimit;
已處理的語句
SQL> oradebug hanganalyze 3
Hang Analysis in G:\ORACLE\diag\rdbms\orcl11g\orcl11g\trace\orcl11g_ora_10972.trc

Trace file G:\ORACLE\diag\rdbms\orcl11g\orcl11g\trace\orcl11g_ora_10972.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1
CPU                 : 4 - type 586, 2 Physical Cores
Process Affinity    : 0x0x00000000
Memory (Avail/Total): Ph:847M/3492M, Ph+PgF:2533M/6983M, VA:1040M/2047M
Instance name: orcl11g
Redo thread mounted by this instance: 1
Oracle process number: 25
Windows thread id: 10972, image: ORACLE.EXE (SHAD)

*** 2013-10-21 15:03:31.765
*** SESSION ID:(575.1) 2013-10-21 15:03:31.765
*** CLIENT ID:() 2013-10-21 15:03:31.765
*** SERVICE NAME:(SYS$USERS) 2013-10-21 15:03:31.765
*** MODULE NAME:(sqlplus.exe) 2013-10-21 15:03:31.765
*** ACTION NAME:() 2013-10-21 15:03:31.765
 
Processing Oradebug command 'setmypid'

*** 2013-10-21 15:03:31.765
Oradebug command 'setmypid' console output:

*** 2013-10-21 15:03:39.175
Processing Oradebug command 'unlimit'

*** 2013-10-21 15:03:39.175
Oradebug command 'unlimit' console output:

*** 2013-10-21 15:03:48.660
Processing Oradebug command 'hanganalyze 3'

*** 2013-10-21 15:03:49.237
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): orcl11g.orcl11g
  oradebug_node_dump_level: 3
  analysis initiated by oradebug
  os thread scheduling delay history: (sampling every 1.000000 secs)
    0.000000 secs at [ 15:03:48 ]
      NOTE: scheduling delay has not been sampled for 0.656762 secs    0.000000 secs from [ 15:03:44 - 15:03:49 ], 5 sec avg
    0.000000 secs from [ 15:02:49 - 15:03:49 ], 1 min avg
    0.000116 secs from [ 14:58:49 - 15:03:49 ], 5 min avg
===============================================================================
 
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 (orcl11g.orcl11g)
                   os id: 10724
              process id: 17, ORACLE.EXE (SHAD)
              session id: 572
        session serial #: 5
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x8000f
                      p3: 'sequence'=0x427
            time in wait: 3 min 13 sec
           timeout after: never
                 wait id: 24
                blocking: 0 sessions
             current sql: delete from t_lf where id=1
             short stack: _ksedsts()+373<
            wait history:
              * time between current wait and wait #1: 0.000373 sec
              1.       event: 'Disk file operations I/O'
                 time waited: 0.000777 sec
                     wait id: 23              p1: 'FileOperation'=0x2
                                              p2: 'fileno'=0x5
                                              p3: 'filetype'=0x2
              * time between wait #1 and #2: 0.000326 sec
              2.       event: 'SQL*Net message from client'
                 time waited: 1.912707 sec
                     wait id: 22              p1: 'driver id'=0x42455100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000001 sec
              3.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 21              p1: 'driver id'=0x42455100
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (orcl11g.orcl11g)
                   os id: 12736
              process id: 20, ORACLE.EXE (SHAD)
              session id: 9
        session serial #: 15
    }
    which is waiting for 'SQL*Net message from client' with wait info:
    {
                      p1: 'driver id'=0x42455100
                      p2: '#bytes'=0x1
            time in wait: 3 min 24 sec
           timeout after: never
                 wait id: 496
                blocking: 1 session
             current sql:
             short stack: _ksedsts()+373
            wait history:
              * time between current wait and wait #1: 0.000015 sec
              1.       event: 'SQL*Net message to client'
                 time waited: 0.000003 sec
                     wait id: 495             p1: 'driver id'=0x42455100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000564 sec
              2.       event: 'db file scattered read'
                 time waited: 0.000744 sec
                     wait id: 494             p1: 'file#'=0x5
                                              p2: 'block#'=0x974
                                              p3: 'blocks'=0xc
              * time between wait #2 and #3: 0.000554 sec
              3.       event: 'db file scattered read'
                 time waited: 0.003634 sec
                     wait id: 493             p1: 'file#'=0x5
                                              p2: 'block#'=0x967
                                              p3: 'blocks'=0xd
    }
 
Chain 1 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
Chain 1 Signature Hash: 0x38c48850
-------------------------------------------------------------------------------
 
===============================================================================
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]):
[8]/1/9/15/33A37DD0/12736/LEAF/
[571]/1/572/5/330D7A30/10724/NLEAF/[8]

*** 2013-10-21 15:03:49.299
===============================================================================
END OF HANG ANALYSIS
===============================================================================

*** 2013-10-21 15:03:49.299
===============================================================================
HANG ANALYSIS DUMPS:
  oradebug_node_dump_level: 3
===============================================================================
 
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[8]/1/9/15/33A37DD0/12736/LEAF/
[571]/1/572/5/330D7A30/10724/NLEAF/[8]
 
 
No processes qualify for dumping.
 
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================

*** 2013-10-21 15:03:49.299
Oradebug command 'hanganalyze 3' console output:
Hang Analysis in G:\ORACLE\diag\rdbms\orcl11g\orcl11g\trace\orcl11g_ora_10972.trc

通過上述分析:大概可以得出sid=572因為請求enq: TX - row lock contention(TX mode=6)被sid=9阻塞

 

3、查詢檢視驗證
SQL> select sid,event from v$session where wait_class#<>6;
 
       SID EVENT
---------- ------------------------------
       572 enq: TX - row lock contention

SQL> select sid,blocking_session,event,p1,p2,p3 from v$session where sid=572;

       SID BLOCKING_SESSION EVENT                                                   P1         P2         P3
---------- ---------------- ----------------------------------------------- ---------- ---------- ----------
       572                9 enq: TX - row lock contention                   1415053318     393245       1058
 
SQL> select * from v$lock where type in('TX','TM');
 
ADDR     KADDR           SID TY        ID1        ID2      LMODE    REQUEST      CTIME      BLOCK
-------- -------- ---------- -- ---------- ---------- ---------- ---------- ---------- ----------
31C81ED8 31C81F04        572 TX     393245       1058          0          6         51          0
0F1DA850 0F1DA880          9 TM      59713          0          3          0         66          0
0F1DA850 0F1DA880        572 TM      59713          0          3          0         51          0
2F48E894 2F48E8D4          9 TX     393245       1058          6          0         66          1
--查詢結果sid=9的會話持有TX MODE=6阻塞sid=572的TX MODE=6的請求,和HANG ANALYSIS分析基本一致。