11g中hanganalyze的格式

从11g开始，Oracle的trace格式相比10g，有很大的改变。hanganalyze trace格式也不例外。

做个小测试，认识一下。

在session1中：

SYS@tst SQL>select * from v$mystat where rownum<2;       SID STATISTIC#      VALUE---------- ---------- ----------       355          0          0SYS@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          0SYS@tst SQL>update scott.syk set loc='BJ' where deptno=10;

然后在session3中，做hanganalyze

SYS@tst SQL>oradebug setmypidStatement processed.SYS@tst SQL>oradebug hanganalyze 3Hang Analysis in /apps/oracle/diag/rdbms/tst/tst/trace/tst_ora_20554.trcSYS@tst SQL>oradebug hanganalyze 3Hang Analysis in /apps/oracle/diag/rdbms/tst/tst/trace/tst_ora_20554.trcSYS@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:              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]来确定。