oracle 11.2.0.3 rac hanganalyze 案例

环境：
rhel6.5 oracle 11.2.0.3.8 rac 两个节点
客户说db无法使用，需要dba介入处理。

dba登陆任一个节点的os，执行了如下的命令:

[oracle@hosta ~]$ sqlplus '/ as sysdba'

SQL*Plus: Release 11.2.0.3.0 Production on Fri Nov 13 19:19:30 2015

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options

SQL> oradebug setorapname reco
Oracle pid: 22, Unix process pid: 13200, image: oracle@hosta (RECO)
SQL> oradebug unlimit
Statement processed.
SQL> oradebug -g all hanganalyze 3
Hang Analysis in /u02/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_13164.trc
SQL> oradebug -g all hanganalyze 3
Hang Analysis in /u02/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_13164.trc
SQL> oradebug -g all dump systemstate 266
Statement processed.
SQL> oradebug -g all dump systemstate 266
Statement processed.
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
[oracle@hosta ~]$ date
Fri Nov 13 19:22:22 CST 2015
[oracle@hosta ~]$ 
--->注意：如上命令的来源：
How to Collect Diagnostics for Database Hanging Issues (文档 ID 452358.1)

/u02/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_13164.trc的内容截取如下：

*** 2015-11-13 19:20:11.392
DIAG sends out oradebug command to nodes [0,1]

*** 2015-11-13 19:20:11.454
****************************************************************
PORADEBUG BEGIN ORIGINATING INST:1 SERIAL:1 PID:24794
PORADATA COMMAND:hanganalyze 3
session (kjzddbx) switches to a new action
PORADATA TRACEFILE /u02/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_13164.trc
PORADEBUG END ORIGINATING INST:1 SERIAL:1 PID:24794
****************************************************************

*** 2015-11-13 19:20:12.060
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): orcl.orcl1, orcl.orcl2
  oradebug_node_dump_level: 3
  analysis initiated by oradebug
  os thread scheduling delay history: (sampling every 1.000000 secs)
    0.000000 secs at [ 19:20:11 ]
      NOTE: scheduling delay has not been sampled for 0.494255 secs    0.000000 secs from [ 19:20:07 - 19:20:12 ], 5 sec avg
    0.000000 secs from [ 19:19:12 - 19:20:12 ], 1 min avg
    0.000124 secs from [ 19:15:12 - 19:20:12 ], 5 min avg
===============================================================================
 
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: 'SQL*Net message from client'<='enq: TX - row lock contention'
     Chain 2 Signature Hash: 0x38c48850
 [c] Chain 3 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
     Chain 3 Signature Hash: 0x38c48850
 
===============================================================================
Non-intersecting chains:
 
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl1)
                   os id: 24694
              process id: 44, oracle@hosta
              session id: 10
        session serial #: 193
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x8000e
                      p3: 'sequence'=0x452
            time in wait: 6 min 10 sec
           timeout after: never
                 wait id: 37
                blocking: 0 sessions
             current sql: update scott.emp set ename=ename|| '1+1' where empno='7369'
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kjusuc()+3619<-ksipgetctxi()+1759<-ksqcmi()+24096<-ksqgtlctx()+3488<-ksqgelctx()+569<-ktuGetTxForXid()+131<-ktcwit1()+313<-kdddgb()+8525<-kdusru()+461<-updrowFastPath()+1209<-qerupFetch()+2554<-updaul()+1309<-updThreePhaseExe()+324<-updexe()+443<-opiexe()+10085<-kpoal8()+2224<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103
            wait history:
              * time between current wait and wait #1: 0.000239 sec
              1.       event: 'gc current block 2-way'
                 time waited: 0.001155 sec
                     wait id: 36              p1: ''=0x4
                                              p2: ''=0x97
                                              p3: ''=0x2000001
              * time between wait #1 and #2: 0.000273 sec
              2.       event: 'Disk file operations I/O'
                 time waited: 0.000010 sec
                     wait id: 35              p1: 'FileOperation'=0x2
                                              p2: 'fileno'=0x4
                                              p3: 'filetype'=0x2
              * time between wait #2 and #3: 0.002898 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 2.574032 sec
                     wait id: 34              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (orcl.orcl1)
                   os id: 18342
              process id: 49, oracle@hosta
              session id: 137
        session serial #: 2227
    }
    which is waiting for 'SQL*Net message from client' with wait info:
    {
                      p1: 'driver id'=0x54435000
                      p2: '#bytes'=0x1
            time in wait: 7 min 44 sec
           timeout after: never
                 wait id: 877
                blocking: 3 sessions
             current sql: <none>
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-read()+14<-nttfprd()+343<-nsbasic_brc()+376<-nsbrecv()+69<-nioqrc()+485<-opikndf2()+978<-opitsk()+847<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+253<-_start()+36
            wait history:
              * time between current wait and wait #1: 0.000301 sec
              1.       event: 'SQL*Net message to client'
                 time waited: 0.000016 sec
                     wait id: 876             p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.001011 sec
              2.       event: 'SQL*Net message from client'
                 time waited: 269 min 8 sec
                     wait id: 875             p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000097 sec
              3.       event: 'SQL*Net message to client'
                 time waited: 0.000006 sec
                     wait id: 874             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
-------------------------------------------------------------------------------
 
===============================================================================
Intersecting chains:
 
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 2 (orcl.orcl2)
                   os id: 24814
              process id: 44, oracle@hostb
              session id: 10
        session serial #: 3041
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x8000e
                      p3: 'sequence'=0x452
            time in wait: 343 min 6 sec
           timeout after: never
                 wait id: 133
                blocking: 0 sessions
             current sql:  update scott.emp set ename=ename|| '2' where empno='7369'
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kjusuc()+3619<-ksipgetctxi()+1759<-ksqcmi()+24096<-ksqgtlctx()+3488<-ksqgelctx()+569<-ktuGetTxForXid()+131<-ktcwit1()+313<-kdddgb()+8525<-kdusru()+461<-updrowFastPath()+1209<-qerupFetch()+2554<-updaul()+1309<-updThreePhaseExe()+324<-updexe()+443<-opiexe()+10085<-kpoal8()+2224<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103
            wait history:
              * time between current wait and wait #1: 0.000407 sec
              1.       event: 'gc cr block 2-way'
                 time waited: 0.002959 sec
                     wait id: 132             p1: ''=0x3
                                              p2: ''=0xf0
                                              p3: ''=0x1f
              * time between wait #1 and #2: 0.000215 sec
              2.       event: 'Disk file operations I/O'
                 time waited: 0.000011 sec
                     wait id: 131             p1: 'FileOperation'=0x2
                                              p2: 'fileno'=0x3
                                              p3: 'filetype'=0x2
              * time between wait #2 and #3: 0.000245 sec
              3.       event: 'gc current block 2-way'
                 time waited: 0.001150 sec
                     wait id: 130             p1: ''=0x4
                                              p2: ''=0x97
                                              p3: ''=0x2000001
    }
    and is blocked by 'instance: 1, os id: 18342, session id: 137',
    which is a member of 'Chain 1'.
 
Chain 2 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
Chain 2 Signature Hash: 0x38c48850
-------------------------------------------------------------------------------
 
-------------------------------------------------------------------------------
Chain 3:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 2 (orcl.orcl2)
                   os id: 1112
              process id: 50, oracle@hostb
              session id: 255
        session serial #: 3581
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x8000e
                      p3: 'sequence'=0x452
            time in wait: 7 min 12 sec
           timeout after: never
                 wait id: 23
                blocking: 0 sessions
             current sql: update scott.emp set ename=ename|| '2+1' where empno='7369'
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kjusuc()+3619<-ksipgetctxi()+1759<-ksqcmi()+24096<-ksqgtlctx()+3488<-ksqgelctx()+569<-ktuGetTxForXid()+131<-ktcwit1()+313<-kdddgb()+8525<-kdusru()+461<-updrowFastPath()+1209<-qerupFetch()+2554<-updaul()+1309<-updThreePhaseExe()+324<-updexe()+443<-opiexe()+10085<-kpoal8()+2224<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103
            wait history:
              * time between current wait and wait #1: 0.005374 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 42.635240 sec
                     wait id: 22              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000005 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000005 sec
                     wait id: 21              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000340 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.000568 sec
                     wait id: 20              p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
    and is blocked by 'instance: 1, os id: 18342, session id: 137',
    which is a member of 'Chain 1'.
 
Chain 3 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'
Chain 3 Signature Hash: 0x38c48850
-------------------------------------------------------------------------------
 
===============================================================================
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [LEAF] [LEAF_NW] 
[level  5] :   3 node dumps -- [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW] 
 
State of ALL nodes-->可以看到，在执行“oradebug -g all hanganalyze 3”命令的节点的diag文件中，才有这个“State of ALL nodes”字样。
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[9]/1/10/193/0x95231978/24694/NLEAF/[136]---->nodenum=9的 session（即:1号实例上sid为10的session）的blocker（阻塞者）为nodenum=136的 session
[136]/1/137/2227/0x95376400/18342/LEAF/------>nodenum=136的 session是blocker（阻塞者）
[481]/2/10/3041/0x95231978/24814/NLEAF/[136]->nodenum=481的 session（即:2号实例上sid为10的session）的blocker（阻塞者）为nodenum=136的 session
[726]/2/255/3581/0x94d0a760/1112/NLEAF/[136]->nodenum=726的 session（即:2号实例上sid为255的session）的blocker（阻塞者）为nodenum=136的 session

*** 2015-11-13 19:20:12.061
===============================================================================
END OF HANG ANALYSIS
===============================================================================

*** 2015-11-13 19:20:12.064
===============================================================================
HANG ANALYSIS DUMPS:
  oradebug_node_dump_level: 3
===============================================================================
 
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[9]/1/10/193/0x95231978/24694/NLEAF/[136]
[136]/1/137/2227/0x95376400/18342/LEAF/
 
 
No processes qualify for dumping.
 
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================
session (kjzddbx) switches to a new action
PORADATA SERIAL:1 RINST:2 RDIAG:31036
PORADATA SERIAL:1 RINST:2 REMOTE EXEC OSPID:31036
PORADATA SERIAL:1 RINST:2 TRACEFILE:/u02/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_31036.trc
PORADATA SERIAL:1 RINST:2  DONE

/u02/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_13164.trc的内容摘录完毕。

 

/u02/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_31036.trc的内容摘录如下：

*** 2015-11-13 19:20:11.423
****************************************************************
PORADEBUG BEGIN ORIGINATING INST:1 SERIAL:1 PID:24794
PORADATA COMMAND:hanganalyze 3
session (kjzddbx) switches to a new action
PORADATA TRACEFILE /u02/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_31036.trc
PORADEBUG END ORIGINATING INST:1 SERIAL:1 PID:24794
****************************************************************

*** 2015-11-13 19:20:12.064
===============================================================================
HANG ANALYSIS DUMPS:
  oradebug_node_dump_level: 3
===============================================================================
 
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[481]/2/10/3041/0x95231978/24814/NLEAF/[136]---->可以看到，sid为10的session的blocker（阻塞者）是 nodenum=136，而这个136不在State of LOCAL nodes中，这说明这个nodenum=136在对方实例上。
[726]/2/255/3581/0x94d0a760/1112/NLEAF/[136]---->可以看到，sid为255的session的blocker（阻塞者）是 nodenum=136，而这个136不在State of LOCAL nodes中，这说明这个nodenum=136在对方实力上。
      ->上面的2是指2号实例，该编号从1开始。
 
No processes qualify for dumping.
 
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================
session (kjzddbx) switches to a new action

*** 2015-11-13 19:20:12.284
Oradebug command console output: <none>

/u02/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_31036.trc的内容摘录完毕。