从11g开始,Oracle的trace格式相比10g,有很大的改变。hanganalyze trace格式也不例外。
创新互联成立于2013年,我们提供高端重庆网站建设公司、成都网站制作、网站设计、网站定制、全网整合营销推广、小程序设计、微信公众号开发、seo优化排名服务,提供专业营销思路、内容策划、视觉设计、程序开发来完成项目落地,为成都VR全景企业提供源源不断的流量和订单咨询。
做个小测试,认识一下。
在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: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]来确定。