从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]来确定。
亿速云「云服务器」,即开即用、新一代英特尔至强铂金CPU、三副本存储NVMe SSD云盘,价格低至29元/月。点击查看>>
免责声明:本站发布的内容(图片、视频和文字)以原创、转载和分享为主,文章观点不代表本网站立场,如果涉及侵权请联系站长邮箱:is@yisu.com进行举报,并提供相关证据,一经查实,将立刻删除涉嫌侵权内容。