oradebug hanganalyze test

目录

--1. session 37 init data

--2. session 46  update no commit

 --3. session 37 update

--4.  oradebug hanganalyze 3

--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