11g中hanganalyze的格式

從11g開始，Oracle的trace格式相比10g，有很大的改變。hanganalyze trace格式也不例外。

做個小測試，認識一下。

在session1中：

SYS@tst SQL>select * from v$mystat where rownum<2;

       SID STATISTIC#      VALUE
---------- ---------- ----------
       355          0          0

SYS@tst SQL>update scott.syk set loc='BJ' where deptno=10;

1 row updated.

在session2中：

SYS@tst SQL>select * from v$mystat where rownum<2;

       SID STATISTIC#      VALUE
---------- ---------- ----------
       246          0          0

SYS@tst SQL>update scott.syk set loc='BJ' where deptno=10;

然后在session3中，做hanganalyze

SYS@tst SQL>oradebug setmypid
Statement processed.
SYS@tst SQL>oradebug hanganalyze 3
Hang Analysis in /apps/oracle/diag/rdbms/tst/tst/trace/tst_ora_20554.trc
SYS@tst SQL>oradebug hanganalyze 3
Hang Analysis in /apps/oracle/diag/rdbms/tst/tst/trace/tst_ora_20554.trc
SYS@tst SQL>exit

然后查看tst_ora_20554.trc

Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (xbtst.xbtst)
                   os id: 20433
              process id: 30, oracle@tstdb-25-220 (TNS V1-V3)
              session id: 246
        session serial #: 7817
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x1001b
                      p3: 'sequence'=0x3ba
            time in wait: 42.648677 sec
           timeout after: never
                 wait id: 13
                blocking: 0 sessions
             current sql: update scott.syk set loc='BJ' where deptno=10
             short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+178<-ksliwat()+2022<-kslwaitctx()+163<-ksqcmi()+2848<-ksqgtlctx()+3501<-ksqgelctx()+557<-ktuGetTxForXid()+131<-ktcwit1()+336<-kdddgb()+8587<-kdusru()+460<-updrowFastPath()+1193<-qerupFetch()+2415<-updaul()+1378<-updThreePhaseExe()+318<-updexe()+638<-opiexe()+10378<-kpoal8()+2380<-opiodr()+917<-ttcpip()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+26
            wait history:
              * time between current wait and wait #1: 0.000855 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 30.441778 sec
                     wait id: 12              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000059 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 11              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000045 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.000465 sec
                     wait id: 10              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (xbtst.xbtst)
                   os id: 20329
              process id: 27, oracle@tstdb-25-220 (TNS V1-V3)
              session id: 355
        session serial #: 2535
    }
    which is waiting for 'SQL*Net message from client' with wait info:
    {
                      p1: 'driver id'=0x62657100
                      p2: '#bytes'=0x1
            time in wait: 51.621284 sec
           timeout after: never
                 wait id: 24
                blocking: 1 session
             current sql: <none>
             short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-read()+14<-ntpfprd()+117<-nsbasic_brc()+376<-nsbrecv()+69<-nioqrc()+495<-opikndf2()+978<-opitsk()+831<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+265<-main()+201<-__libc_start_main()+245
            wait history:
              * time between current wait and wait #1: 0.000007 sec
              1.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 23              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.004410 sec
              2.       event: 'SQL*Net message from client'
                 time waited: 29.579867 sec
                     wait id: 22              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000003 sec
              3.       event: 'SQL*Net message to client'
                 time waited: 0.000000 sec
                     wait id: 21              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
    }
 
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]):
[245]/1/246/7817/0xf2d616a8/20433/NLEAF/[354]
[354]/1/355/2535/0xf2ee55c8/20329/LEAF/

*** 2016-10-11 13:28:25.479
===============================================================================
END OF HANG ANALYSIS

解決幾個點：

[adjlist]：這個可以看做是[nodenum]

NLEAF：這個是waiter

LEAF：這個是blocker

nodenum[245]被adjlist[354]阻塞，nodenum[354]沒有阻塞者。

[354]這一行中，sid為355，state為LEAF，所以355是blocker，對應上面的session1中執行的語句。

[245]這一行中，sid為246，state為NLEAF，所以246是waiter，對應上面的session2中執行的語句。

因此在分析hanganalyze時，可以通過LEAF來初步定位blocker，然后再通過NLEAF、[adjlist]來確定。