目录
--2. session 46 update no commit
--5. check hanganalyze tracefile
基本用法
hanganalyze有两种使用方法:
a.alter session set events 'immediate trace name hanganalyze level <level>';
会话级别,单实例和rac都可以使用。
b.--for 单实例
oradebug hanganalyze <level>
--for RAC
oradebug setmypid --跟踪当前会话
oradebug setinst all --rac环境
oradebug -g def hanganalyze <level>
oradebug unlimit --取消trace文件大小限制
oradebug tracefile_name --查看trace文件名及位置
此外oredebug工具常见的用处如下:
oradebug setospid --跟踪系统进程
oradebug setorapid --跟踪ORACLE进程
-------------------------------------------
level等级和概念:
1-2:只有hanganalyze输出,不dump任何进程
3:level2+dump出在in_hang状态的进程
4:level3+dump出在等待链里面的blockers(状态为leaf/leaf_nw/ign_dmp)
5:level4+dump出所有在等待链中的进程(状态为nleaf)
Oracle官方建议不要超过level 3。level 3 对于分析问题足够了。超过level 3会给系统带来额外负担。
--1. session 37 init data
--session 37
select userenv('sid') from dual;
--check version
select * from v$version;
select sid,serial# from v$session where sid=(select userenv('SID') from dual);
--create table
create table test (id number,name varchar2(10)) tablespace users;
select * from test;
insert into test values(1,'111');
insert into test values(2,'222');
commit;
--2. session 46 update no commit
select sid,serial# from v$session where sid=(select userenv('SID') from dual);
select userenv('sid') from dual;
--46
update wytest set name='test' where id = 1;
--not commit
--3. session 37 update
update test set name = 'test1' where id = 1;
--4. oradebug hanganalyze 3
[oracle@rhel64 trace]$ sqlplus sys/oracle@orcl as sysdba
SQL> oradebug setmypid
Statement processed.
SQL> oradebug setinst all
SQL> oradebug hanganalyze 3;
Hang Analysis in /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_101632.trc
SQL> exit
--5. check hanganalyze tracefile
HANGANALYZE跟踪文件分析:跟踪文件中最关键的部分是STATE OF NODES。对于9i该部分的条目结构为:
[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
nodenum:定义每个session的序列号
sid:session的sid
sess_srno:session的Serial#
ospid:OS的进程ID
state:node的状态
adjlist:表示blocker node
predecessor:表示waiter node
State有如下几种状态:
- IN_HANG:如果Session处于这种状态,表示Session遇到deadlock或者处于hung状态。
- LEAF/LEAF_NW:这些Session通常是“blocker”或者是等待某些资源的“slow” node,通过字段“predecessor” 可以很容易标识出这些node。
- NLEAF:这些Session通常被认为是“stuck”会话,意味着这些Session在等待某些 Session的资源。通过字段“adjlist”可以很容易的定义该进程的blocker。
- IGN/IGN_DMP:这些Session通常是IDLE Session。
Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_101632.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
Build label: RDBMS_19.3.0.0.0DBRU_LINUX.X64_190417
ORACLE_HOME: /u01/app/oracle/product/19.3.0/dbhome_1
System name: Linux
Node name: rhel64
Release: 4.18.0-193.el8.x86_64
Version: #1 SMP Fri Mar 27 14:35:58 UTC 2020
Machine: x86_64
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 65
Unix process pid: 101632, image: oracle@rhel64
*** 2023-03-25T14:33:03.786581+08:00
*** SESSION ID:(154.65305) 2023-03-25T14:33:03.786629+08:00
*** CLIENT ID:() 2023-03-25T14:33:03.786645+08:00
*** SERVICE NAME:(orcl) 2023-03-25T14:33:03.786659+08:00
*** MODULE NAME:(sqlplus@rhel64 (TNS V1-V3)) 2023-03-25T14:33:03.786673+08:00
*** ACTION NAME:() 2023-03-25T14:33:03.786686+08:00
*** CLIENT DRIVER:(SQL*PLUS) 2023-03-25T14:33:03.786697+08:00
Processing Oradebug command 'hanganalyze level 3'
*** 2023-03-25T14:33:03.787131+08:00
Error while executing Oradebug command 'hanganalyze level 3':
ORA-01858: a non-numeric character was found where a numeric was expected
*** 2023-03-25T14:33:03.787255+08:00
Oradebug command 'hanganalyze level 3' console output: <none>
*** 2023-03-25T14:34:43.704693+08:00
Processing Oradebug command 'hanganalyze 3'
*** 2023-03-25T14:34:43.734905+08:00
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): orcl.orcl
oradebug_node_dump_level: 3
analysis initiated by oradebug
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 14:34:43 ]
NOTE: scheduling delay has not been sampled for 0.395898 secs
0.000000 secs from [ 14:34:39 - 14:34:44 ], 5 sec avg
0.000000 secs from [ 14:33:43 - 14:34:44 ], 1 min avg
0.000000 secs from [ 14:29:44 - 14:34:44 ], 5 min avg
vktm time drift history
09:59:49.402 LR fwd drift by 3659564736 us at 1679709589
12:30:13.870 LR fwd drift by 9000000 us at 1679718613
13:00:28.252 LR fwd drift by 9000000 us at 1679720428
===============================================================================
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 (orcl.orcl)
os id: 100650
process id: 54, oracle@rhel64
session id: 37
session serial #: 59439
module name: 0 (TOAD 14.1.120.923)
}
is waiting for 'enq: TX - row lock contention' with wait info:
{
p1: 'name|mode'=0x54580006
p2: 'usn<<16 | slot'=0x9001b
p3: 'sequence'=0x428
time in wait: 4 min 59 sec
timeout after: never
wait id: 387
blocking: 0 sessions
current sql_id: 1978774822
current sql: update test name = 'test1' where id = 1
short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+200<-__sighandler()<-semtimedop()+14<-skgpwwait()+187<-ksliwat()+2218<-kslwaitctx()+188<-ksqcmi()+21656<-ksqgtlctx()+6620<-ksqgelctx()+838<-ktuGetTxForXid()+230<-ktcwit1()+367<-kdddgb()+5478<-kdusru()+458<-updrowFastPath()+1209<-qerupUpdRow()+1548<-qerupRopRowsets()+259<-kdstf110110100001000km()+12357<-kdsttgr()+2160<-qertbFetch()+1089<-qerupFetch()+1634<-updaul()+1416<-updThreePhaseExe()+340<-updexe()+405<-opiexe()+11573<-kpoal8()+2387<-opiodr()+1202<-ttcpip()
wait history:
* time between current wait and wait #1: 0.003267 sec
1. event: 'SQL*Net message from client'
time waited: 3 min 32 sec
wait id: 386 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000019 sec
2. event: 'SQL*Net message to client'
time waited: 0.000006 sec
wait id: 385 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000275 sec
3. event: 'SQL*Net message from client'
time waited: 0.003246 sec
wait id: 384 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (orcl.orcl)
os id: 101269
process id: 60, oracle@rhel64
session id: 46
session serial #: 54358
module name: 0 (TOAD 14.1.120.923)
}
which is waiting for 'SQL*Net message from client' with wait info:
{
p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
time in wait: 5 min 54 sec
timeout after: never
wait id: 161
blocking: 1 session
current sql_id: 0
current sql: <none>
short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+200<-__sighandler()<-__read()+16<-snttread()+16<-nttfprd()+354<-nsbasic_brc()+399<-nioqrc()+438<-opikndf2()+999<-opitsk()+905<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+243<-0x5541F689495641D7
wait history:
* time between current wait and wait #1: 0.000019 sec
1. event: 'SQL*Net message to client'
time waited: 0.000009 sec
wait id: 160 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.009341 sec
2. event: 'SQL*Net message from client'
time waited: 1 min 39 sec
wait id: 159 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000026 sec
3. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 158 p1: 'driver id'=0x54435000
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]):
[36]/1/37/59439/0x6e4e3790/100650/NLEAF/[45]
[45]/1/46/54358/0x6e4f9eb8/101269/LEAF/
*** 2023-03-25T14:34:43.737383+08:00
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2023-03-25T14:34:43.737466+08:00
===============================================================================
HANG ANALYSIS DUMPS:
oradebug_node_dump_level: 3
===============================================================================
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[36]/1/37/59439/0x6e4e3790/100650/NLEAF/[45]
[45]/1/46/54358/0x6e4f9eb8/101269/LEAF/
No processes qualify for dumping.
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================
*** 2023-03-25T14:34:43.737647+08:00
Oradebug command 'hanganalyze 3' console output:
Hang Analysis in /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_101632.trc