oracle hanganalyze和systemstate使用测试

红太狼 2022-05-31 05:10 161阅读 0赞

为什么要使用hanganalyze  
Oracle 数据库“真的”hang住了，可以理解为数据库内部发生死锁。因为普通的DML死锁，oracle服务器会自动监测他们的依赖关系，并回滚其中一个操作，终止这种相互等待的局面。而当这种死锁发生在争夺内核级别的资源（比如说是pins或latches）时，Oracle并不能自动的监测并处理这种死锁。  
其实很多时候数据库并没有hang住，而只是由于数据库的性能问题，处理的时间比较长而已。  
Hanganalyze工具使用内核调用检测会话在等待什么资源，报告出占有者和等待者的相互关系。另外，它还会将一些比较”interesting”的进程状态dump出来，这个取决于我们使用hanganalyze的分析级别。  
hanganalyze工具从oracle8i第二版开始提供，到9i增强了诊断RAC环境下的“集群范围”的信息，这意味着它将会报告出整个集群下的所有会话的信息。  
目前有三种使用hanganalyze的方法:  
一种是会话级别的：

SQL>ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level <level>';

一种是实例级别:

SQL>ORADEBUG hanganalyze <level>

一种是集群范围的：

SQL>ORADEBUG setmypid
    SQL>ORADEBUG setinst all
    SQL>ORADEBUG -g def hanganalyze <level>

各个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会给系统带来额外负担。

下面用实验说明如何使用hanganalyze

1.session1更新行数据

SQL> conn test/test
    Connected.
    SQL> create table tb_hang(id int,name varchar2(20));
    
    Table created.
    
    SQL> insert into tb_hang values(1,'yu');
    
    1 row created.
    
    SQL> commit;
    
    Commit complete.
    
    SQL> select userenv('sid') from dual;
    
    USERENV('SID')
    --------------
    	  1285
    
    SQL> update tb_hang set name='shi' where id=1; 
    
    1 row updated.
    
    这个时候不要提交

2.session2同样更新session1更新的行

SQL> conn test/test
    Connected.
    SQL> select userenv('sid') from dual;
    
    USERENV('SID')
    --------------
    	  1044
    
    SQL> update tb_hang set name='shi' where id=1;

这个时候已经hang住了

3.session3使用hangalyze生成trace文件

orcl:/home/oracle@oracle>sqlplus / as sysdba
    
    SQL*Plus: Release 11.2.0.4.0 Production on Thu Feb 8 09:10:51 2018
    
    Copyright (c) 1982, 2013, Oracle.  All rights reserved.
    
    
    Connected to:
    Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    
    SQL> oradebug hanganalyze 3;
    Hang Analysis in /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_162680.trc
    SQL> exit

4.查看trace 文件的内容

orcl:/home/oracle@oracle>vi /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_162680.trc
    Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_162680.trc
    Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
    With the Partitioning, OLAP, Data Mining and Real Application Testing options
    ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
    System name:	Linux
    Node name:	oracle
    Release:	2.6.32-431.el6.x86_64
    Version:	#1 SMP Fri Nov 22 03:15:09 UTC 2013
    Machine:	x86_64
    Instance name: orcl
    Redo thread mounted by this instance: 1
    Oracle process number: 105
    Unix process pid: 162680, image: oracle@oracle (TNS V1-V3)
    
    
    *** 2018-02-08 09:11:11.573
    *** SESSION ID:(1248.12215) 2018-02-08 09:11:11.573
    *** CLIENT ID:() 2018-02-08 09:11:11.573
    *** SERVICE NAME:(SYS$USERS) 2018-02-08 09:11:11.573
    *** MODULE NAME:(sqlplus@oracle (TNS V1-V3)) 2018-02-08 09:11:11.573
    *** ACTION NAME:() 2018-02-08 09:11:11.573
     
    Processing Oradebug command 'hanganalyze 3'
    
    *** 2018-02-08 09:11:12.472
    ===============================================================================
    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 [ 09:11:11 ]
          NOTE: scheduling delay has not been sampled for 0.557785 secs    0.000000 secs from [ 09:11:07 - 09:11:12 ], 5 sec avg
        0.000000 secs from [ 09:10:12 - 09:11:12 ], 1 min avg
        0.000000 secs from [ 09:06:13 - 09:11:12 ], 5 min avg
      vktm time drift history
    ===============================================================================
     
    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
     [b] Chain 2 Signature: 'Streams AQ: deallocate messages from Streams Pool'
         Chain 2 Signature Hash: 0x22faf522
     [c] Chain 3 Signature: 'EMON slave idle wait'
         Chain 3 Signature Hash: 0x9fbbc886
     
    ===============================================================================
    Non-intersecting chains:
     
    -------------------------------------------------------------------------------
    Chain 1:
    -------------------------------------------------------------------------------
        Oracle session identified by:
        {
                    instance: 1 (orcl.orcl)
                       os id: 162261
                  process id: 104, oracle@oracle (TNS V1-V3)
                  session id: 1044
            session serial #: 22559
        }
        is waiting for 'enq: TX - row lock contention' with wait info:
        {
                          p1: 'name|mode'=0x54580006
                          p2: 'usn<<16 | slot'=0x5001b
                          p3: 'sequence'=0x83ba
                time in wait: 39.344626 sec
               timeout after: never
                     wait id: 27
                    blocking: 0 sessions
                 current sql: update tb_hang set name=:"SYS_B_0" where id=:"SYS_B_1"
                 short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+163<-ksqcmi()+2848<-ksqgtlctx()+3501<-ksqgel
    ctx()+557<-ktuGetTxForXid()+131<-ktcwit1()+336<-kdddgb()+8364<-kdusru()+461<-kauupd()+412<-updrow()+2167<-qerupFetch()+832<-updaul()+1321<-updThreePhaseExe()+318<-updexe()+418<-opiexe()+10378<-kpoal8()+2118<-o
    piodr()+917<-ttcpip()+2183<-opitsk()+1710<-opiino()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain
                wait history:
                  * time between current wait and wait #1: 0.007105 sec
                  1.       event: 'SQL*Net message from client'
                     time waited: 24.601697 sec
                         wait id: 26              p1: 'driver id'=0x62657100
                                                  p2: '#bytes'=0x1
                  * time between wait #1 and #2: 0.000001 sec
              2.       event: 'SQL*Net message to client'
                     time waited: 0.000000 sec
                         wait id: 25              p1: 'driver id'=0x62657100
                                                  p2: '#bytes'=0x1
                  * time between wait #2 and #3: 0.000005 sec
                  3.       event: 'SQL*Net message from client'
                     time waited: 0.000078 sec
                         wait id: 24              p1: 'driver id'=0x62657100
                                                  p2: '#bytes'=0x1
        }
        and is blocked by
     => Oracle session identified by:
        {
                    instance: 1 (orcl.orcl)
                       os id: 160578
                  process id: 106, oracle@oracle (TNS V1-V3)
                  session id: 1285
            session serial #: 47113
        }
        which is waiting for 'SQL*Net message from client' with wait info:
        {
                          p1: 'driver id'=0x62657100
                          p2: '#bytes'=0x1
                time in wait: 2 min 22 sec
               timeout after: never
                     wait id: 62
                    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<-opii
    no()+969<-opiodr()+917<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+265<-main()+201<-__libc_start_main()+253
                wait history:
                  * time between current wait and wait #1: 0.000006 sec
                  1.       event: 'SQL*Net message to client'
                     time waited: 0.000004 sec
                         wait id: 61              p1: 'driver id'=0x62657100
                                                  p2: '#bytes'=0x1
                  * time between wait #1 and #2: 0.143813 sec
                  2.       event: 'SQL*Net message from client'
                     time waited: 25.775520 sec
                         wait id: 60              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.000002 sec
                         wait id: 59              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

有的使用hanganalyze 要结合systemstate使用，下面简单介绍systemstate如何使用：

orcl:/u01/src@oracle>sqlplus -prelim / as sysdba
    
    SQL*Plus: Release 11.2.0.4.0 Production on Thu Feb 8 10:05:56 2018
    
    Copyright (c) 1982, 2013, Oracle.  All rights reserved.
    
    SQL> oradebug setmypid
    Statement processed.
    SQL> oradebug unlimit
    Statement processed.
    SQL> oradebug dump systemstate 266
    Statement processed.
    SQL> oradebug dump systemstate 266
    Statement processed.
    SQL> oradebug tracefile_name
    /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_192754.trc
    SQL> exit
    Disconnected from ORACLE

通过ass109.awk文件，可以很容易将trace文件里的内容理出脉络来，清晰的发现问题所在。

orcl:/u01/src@oracle>ll ass109.awk 
    -rw-r--r-- 1 root root 34549 2月   8 09:51 ass109.awk
    
    orcl:/u01/src@oracle>awk -f ass109.awk /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_192754.trc
    
    Starting Systemstate 1
    ..............................................................................
    ......................................
    Starting Systemstate 2
    ..............................................................................
    ....................................
    Ass.Awk Version 1.0.9 - Processing /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_192754.trc
    
    System State 1
    ~~~~~~~~~~~~~~~~
    1:                                      
    2:  0: waiting for 'pmon timer'         
    3:  0: waiting for 'rdbms ipc message'  
    4:  0: waiting for 'VKTM Logical Idle Wait' 
    5:  0: waiting for 'rdbms ipc message'  
    6:  0: waiting for 'DIAG idle wait'     
    7:  0: waiting for 'rdbms ipc message'  
    8:  0: waiting for 'DIAG idle wait'     
    9:  0: waiting for 'rdbms ipc message'  
    10: 0: waiting for 'rdbms ipc message'  
    11: 0: waiting for 'rdbms ipc message'  
    12: 0: waiting for 'rdbms ipc message'  
    13: 0: waiting for 'rdbms ipc message'  
    14: 0: waiting for 'rdbms ipc message'  
    15: 0: waiting for 'rdbms ipc message'  
    16: 0: waiting for 'rdbms ipc message'  
    17: 0: waiting for 'rdbms ipc message'  
    18: 0: waiting for 'rdbms ipc message'  
    19: 0: waiting for 'rdbms ipc message'  
    20: 0: waiting for 'rdbms ipc message'  
    21: 0: waiting for 'rdbms ipc message'  
    22: 0: waiting for 'rdbms ipc message'  
    23: 0: waiting for 'rdbms ipc message'  
    24: 0: waiting for 'rdbms ipc message'  
    25: 0: waiting for 'rdbms ipc message'  
    26: 0: waiting for 'rdbms ipc message'  
    27: 0: waiting for 'rdbms ipc message'  
    28:                                     
    29: 0: waiting for 'rdbms ipc message'  
    30: 0: waiting for 'rdbms ipc message'  
    31: 0: waiting for 'rdbms ipc message'  
    32:                                     
    33:                                     
    34:                                     
    35:                                     
    36:                                     
    37:                                     
    38:                                     
    39:                                     
    40:                                     
    41:                                     
    42:                                     
    43:                                     
    44:                                     
    45:                                     
    46:                                     
    47:                                     
    48:                                     
    49:                                     
    50:                                     
    51:                                     
    52:                                     
    53:                                     
    54:                                     
    55:                                     
    56:                                     
    57:                                     
    58:                                     
    59:                                     
    60:                                     
    61:                                     
    62:                                     
    63:                                     
    64:                                     
    65: 0: waiting for 'SQL*Net message from client' 
    66: 0: waiting for 'rdbms ipc message'  
    67: 0: waiting for 'rdbms ipc message'  
    68: 0: waiting for 'rdbms ipc message'  
    69: 0: waiting for 'rdbms ipc message'  
    70: 0: waiting for 'rdbms ipc message'  
    71: 0: waiting for 'VKRM Idle'          
    72: 0: waiting for 'Streams AQ: qmn coordinator idle wait' 
    73: 0: waiting for 'Streams AQ: emn coordinator idle wait' 
    74: 0: waiting for 'SQL*Net message from client' 
    75: 0: waiting for 'SQL*Net message from client' 
    76: 0: waiting for 'SQL*Net message from client' 
    77: 0: waiting for 'SQL*Net message from client' 
    78: 9: waited for 'Streams AQ: waiting for time management or cleanup tasks' 
    79: 0: waiting for 'SQL*Net message from client' 
    80: 0: waiting for 'SQL*Net message from client' 
    81: 0: waiting for 'SQL*Net message from client' 
    82: 0: waiting for 'SQL*Net message from client' 
    83: 0: waiting for 'SQL*Net message from client' 
    84: 0: waiting for 'SQL*Net message from client' 
    85: 0: waiting for 'SQL*Net message from client' 
    86: 0: waiting for 'SQL*Net message from client' 
    87: 0: waiting for 'PL/SQL lock timer'  
    88: 0: waiting for 'EMON slave idle wait' 
    89: 0: waiting for 'EMON slave idle wait' 
    90: 0: waiting for 'EMON slave idle wait' 
    91: 0: waiting for 'EMON slave idle wait' 
    92: 0: waiting for 'EMON slave idle wait' 
    93: 0: waiting for 'SQL*Net message from client' 
    94: 0: waiting for 'SQL*Net message from client' 
    95: 0: waiting for 'rdbms ipc message'  
    96: 0: waiting for 'SQL*Net message from client' 
    97: 0: waiting for 'SQL*Net message from client' 
    98: 0: waiting for 'SQL*Net message from client' 
    99: 0: waiting for 'SQL*Net message from client' 
    100:0: waiting for 'SQL*Net message from client' 
    101:0: waiting for 'SQL*Net message from client' 
    102:0: waiting for 'SQL*Net message from client' 
    103:0: waiting for 'Space Manager: slave idle wait' 
    104:0: waiting for 'enq: TX - row lock contention'[Enqueue TX-0005001B-000083BA]  //--可见104进程即V$PROCESS的PID，为上述的会话2正在等待TX锁
    105:0: waiting for 'SQL*Net message from client' 
    106:0: waiting for 'SQL*Net message from client' 
    107:0: waiting for 'SQL*Net message from client' 
    108:0: waiting for 'SQL*Net message from client' 
    109:0: waiting for 'SQL*Net message from client' 
    110:0: waiting for 'SQL*Net message from client' 
    111:0: waiting for 'SQL*Net message from client' 
    112:                                    
    113:0: waiting for 'Streams AQ: qmn slave idle wait' 
    114:                                    
    121:0: waiting for 'rdbms ipc message'  
    134:0: waiting for 'Streams AQ: deallocate messages from Streams Pool' 
    Blockers
    ~~~~~~~~
    
    	Above is a list of all the processes. If they are waiting for a resource
    	then it will be given in square brackets. Below is a summary of the
    	waited upon resources, together with the holder of that resource.
    	Notes:
    	~~~~~
    	 o A process id of '???' implies that the holder was not found in the
    	   systemstate.
    
                        Resource Holder State
    Enqueue TX-0005001B-000083BA   106: 0: waiting for 'SQL*Net message from client'
    
    Object Names
    ~~~~~~~~~~~~
    Enqueue TX-0005001B-000083BA	                              
    
    System State 2
    ~~~~~~~~~~~~~~~~
    1:                                      
    2:  0: waiting for 'pmon timer'         
    3:  0: waiting for 'rdbms ipc message'  
    4:  0: waiting for 'VKTM Logical Idle Wait' 
    5:  0: waiting for 'rdbms ipc message'  
    6:  0: waiting for 'DIAG idle wait'     
    7:  0: waiting for 'rdbms ipc message'  
    8:  0: waiting for 'DIAG idle wait'     
    9:  0: waiting for 'rdbms ipc message'  
    10: 0: waiting for 'rdbms ipc message'  
    11: 0: waiting for 'rdbms ipc message'  
    12: 0: waiting for 'rdbms ipc message'  
    13: 0: waiting for 'rdbms ipc message'  
    14: 0: waiting for 'rdbms ipc message'  
    15: 0: waiting for 'rdbms ipc message'  
    16: 0: waiting for 'rdbms ipc message'  
    17: 0: waiting for 'rdbms ipc message'  
    18: 0: waiting for 'rdbms ipc message'  
    19: 0: waiting for 'rdbms ipc message'  
    20: 0: waiting for 'rdbms ipc message'  
    21: 0: waiting for 'rdbms ipc message'  
    22: 0: waiting for 'rdbms ipc message'  
    23: 0: waiting for 'rdbms ipc message'  
    24: 0: waiting for 'rdbms ipc message'  
    25: 0: waiting for 'rdbms ipc message'  
    26: 0: waiting for 'rdbms ipc message'  
    27: 0: waiting for 'rdbms ipc message'  
    28: 0: waiting for 'smon timer'         
    29: 0: waiting for 'rdbms ipc message'  
    30: 0: waiting for 'rdbms ipc message'  
    31: 0: waiting for 'rdbms ipc message'  
    32:                                     
    33:                                     
    34:                                     
    35:                                     
    36:                                     
    37:                                     
    38:                                     
    39:                                     
    40:                                     
    41:                                     
    42:                                     
    43:                                     
    44:                                     
    45:                                     
    46:                                     
    47:                                     
    48:                                     
    49:                                     
    50:                                     
    51:                                     
    52:                                     
    53:                                     
    54:                                     
    55:                                     
    56:                                     
    57:                                     
    58:                                     
    59:                                     
    60:                                     
    61:                                     
    62:                                     
    63:                                     
    64:                                     
    65: 0: waiting for 'SQL*Net message from client' 
    66: 0: waiting for 'rdbms ipc message'  
    67: 0: waiting for 'rdbms ipc message'  
    68: 0: waiting for 'rdbms ipc message'  
    69: 0: waiting for 'rdbms ipc message'  
    70: 0: waiting for 'rdbms ipc message'  
    71: 0: waiting for 'VKRM Idle'          
    72: 0: waiting for 'Streams AQ: qmn coordinator idle wait' 
    73: 0: waiting for 'Streams AQ: emn coordinator idle wait' 
    74: 0: waiting for 'SQL*Net message from client' 
    75: 0: waiting for 'SQL*Net message from client' 
    76: 0: waiting for 'SQL*Net message from client' 
    77: 0: waiting for 'SQL*Net message from client' 
    78: 9: waited for 'Streams AQ: waiting for time management or cleanup tasks' 
    79: 0: waiting for 'SQL*Net message from client' 
    80: 0: waiting for 'SQL*Net message from client' 
    81: 0: waiting for 'SQL*Net message from client' 
    82: 0: waiting for 'SQL*Net message from client' 
    83: 0: waiting for 'SQL*Net message from client' 
    84: 0: waiting for 'SQL*Net message from client' 
    85: 0: waiting for 'SQL*Net message from client' 
    86: 0: waiting for 'SQL*Net message from client' 
    87: 0: waiting for 'PL/SQL lock timer'  
    88: 0: waiting for 'EMON slave idle wait' 
    89: 0: waiting for 'EMON slave idle wait' 
    90: 0: waiting for 'EMON slave idle wait' 
    91: 0: waiting for 'EMON slave idle wait' 
    92: 0: waiting for 'EMON slave idle wait' 
    93: 0: waiting for 'SQL*Net message from client' 
    94: 0: waiting for 'SQL*Net message from client' 
    95: 0: waiting for 'rdbms ipc message'  
    96: 0: waiting for 'SQL*Net message from client' 
    97: 0: waiting for 'SQL*Net message from client' 
    98: 0: waiting for 'SQL*Net message from client' 
    99: 0: waiting for 'SQL*Net message from client' 
    100:0: waiting for 'SQL*Net message from client' 
    101:0: waiting for 'SQL*Net message from client' 
    102:0: waiting for 'SQL*Net message from client' 
    103:0: waiting for 'Space Manager: slave idle wait' 
    104:0: waiting for 'enq: TX - row lock contention'[Enqueue TX-0005001B-000083BA] 
    105:0: waiting for 'SQL*Net message from client' 
    106:0: waiting for 'SQL*Net message from client' 
    107:0: waiting for 'SQL*Net message from client' 
    108:0: waiting for 'SQL*Net message from client' 
    109:0: waiting for 'SQL*Net message from client' 
    110:0: waiting for 'SQL*Net message from client' 
    111:0: waiting for 'SQL*Net message from client' 
    113:0: waiting for 'Streams AQ: qmn slave idle wait' 
    121:0: waiting for 'rdbms ipc message'  
    134:0: waiting for 'Streams AQ: deallocate messages from Streams Pool' 
    Blockers
    ~~~~~~~~
    
    	Above is a list of all the processes. If they are waiting for a resource
    	then it will be given in square brackets. Below is a summary of the
    	waited upon resources, together with the holder of that resource.
    	Notes:
    	~~~~~
    	 o A process id of '???' implies that the holder was not found in the
    	   systemstate.
    
                        Resource Holder State
    Enqueue TX-0005001B-000083BA   106: 0: waiting for 'SQL*Net message from client'
    
    Object Names
    ~~~~~~~~~~~~
    Enqueue TX-0005001B-000083BA	                              
    
    
    150787 Lines Processed.