Oracle HANGANALYZE 功能診斷 DB hanging .

 

 

一.  HANGANALYZE 的2種使用方式：

（1） The “HANGANALYZE” command is available since Oracle Release 8.1.6. In Oracle9i it was enhanced to provide “cluster wide” information in Real Application Cluster (RAC) environments on a single shot. The meaning of this is that it will generate information for all the sessions in the cluster regardless of the instance that issued the command.

       HANGANALYZE may be executed using the following syntax:

 

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

-- 該命令對於RAC，會收集所有節點上的資訊

 

（2）logged in with the “SYSDBA” role,then run the following command:

       SQL>ORADEBUG hanganalyze

       --for 單例項

 

       To perform cluster wide HANGANALYZE use the following syntax:

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

       --for RAC 例項

 

The levels are defined as follows:

10	Dump all processes (IGN state)
5	Level 4 + Dump all processes involved in wait chains (NLEAF state)
4	Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state)
3	Level 2 + Dump only processes thought to be in a hang (IN_HANG state)
1-2	Only HANGANALYZE output, no process dump at all

 

       注意：如果Level過大的話會產生大量的跟蹤檔案並影響系統的I/O效能，Oracle建議不要採用3級以上的跟蹤。

 

 

二. 示例1：

這是我的一個測試的RAC 環境。

SQL> select instance_name from gv$instance;

 

INSTANCE_NAME

----------------

dave1

dave2

 

SQL> alter session set events 'immediate trace name HANGANALYZE level 3';

Session altered.

 

--獲取trace 檔名稱和路徑，該指令碼會放在最後貼出來

SQL> @/u01/getTracePath.sql

 

trace_file_name

--------------------------------------------------------------------------------

/u01/app/oracle/admin/rac/udump/dave1_ora_20962.trc

/u01/app/oracle/admin/rac/udump/dave2_ora_20962.trc

 

[oracle@rac1 u01]$ cat getTracePath.sql

SELECT      d.VALUE

         || '/'

         || LOWER (RTRIM (i.INSTANCE, CHR (0)))

         || '_ora_'

         || p.spid

         || '.trc'

        AS "trace_file_name"

  FROM   (SELECT   p.spid  FROM   v$mystat m, v$session s, v$process p

      WHERE   m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

         (SELECT   t.INSTANCE  FROM   v$thread t, v$parameter v

           WHERE   v.NAME = 'thread'

          AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

         (SELECT   VALUE FROM   v$parameter

           WHERE   NAME = 'user_dump_dest') d;

 

--注意，如果是在節點1上執行的HANGANALYZE命令，就到節點1上去查詢，該trace 檔案裡包含了所有session的資訊。 我是在dave1上執行的，所以這裡的沒有dave2_ora_20962.trc 檔案。

 

 

開啟trace 檔案看一下：

[oracle@rac1 u01]$ cat /u01/app/oracle/admin/rac/udump/dave1_ora_20962.trc    

/u01/app/oracle/admin/rac/udump/dave1_ora_20962.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production

With the Partitioning, Real Application Clusters, OLAP and Data Mining options

ORACLE_HOME = /u01/app/oracle/product/10.2.0/db_1

System name:    Linux

Node name:      rac1

Release:        2.6.18-194.el5

Version:        #1 SMP Tue Mar 16 21:52:43 EDT 2010

Machine:        i686

Instance name: dave1

Redo thread mounted by this instance: 1

Oracle process number: 23

Unix process pid: 20962, image: oracle@rac1 (TNS V1-V3)

 

 

*** SERVICE NAME:(SYS$USERS) 2011-04-13 22:59:43.052

*** SESSION ID:(125.52764) 2011-04-13 22:59:43.052

*** 2011-04-13 22:59:43.052

==============

HANG ANALYSIS:

==============

Open chains found:

Other chains found:

Chain 1 : :

    <0/125/52764/0x30e1dff4/20962/No Wait>

Chain 2 : :

    <0/129/26/0x30e23580/4576/Streams AQ: qmn slave idle wait>

Chain 3 : :

    <0/130/16238/0x30e22fcc/4300/jobq slave wait>

Chain 4 : :

    <0/134/1/0x30e21eb0/669/Streams AQ: waiting for time man>

Chain 5 : :

    <0/138/11/0x30e21348/654/Streams AQ: waiting for messages>

Chain 6 : :

    <0/139/1/0x30e207e0/428/Streams AQ: qmn coordinator idle>

Chain 7 : :

    <0/169/1/0x30e16de4/32435/DIAG idle wait>

Extra information that will be dumped at higher levels:

[level  5] :   7 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]

[level 10] :  23 node dumps -- [IGN]

 

State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):

[124]/0/125/52764/0x30ee3870/20962/SINGLE_NODE_NW/1/2//none

[128]/0/129/26/0x30ee8340/4576/SINGLE_NODE/3/4//none

[129]/0/130/16238/0x30ee95f4/4300/SINGLE_NODE/5/6//none

[130]/0/131/2/0x30eea8a8/680/IGN/7/8//none

[131]/0/132/2/0x30eebb5c/663/IGN/9/10//none

[133]/0/134/1/0x30eee0c4/669/SINGLE_NODE/11/12//none

[134]/0/135/27202/0x30eef378/17839/IGN/13/14//none

[137]/0/138/11/0x30ef2b94/654/SINGLE_NODE/15/16//none

[138]/0/139/1/0x30ef3e48/428/SINGLE_NODE/17/18//none

...

[168]/0/169/1/0x30f16f60/32435/SINGLE_NODE/57/58//none

[169]/0/170/1/0x30f18214/32428/IGN/59/60//none

====================

END OF HANG ANALYSIS

====================

[oracle@rac1 u01]$

 

 

三.  示例二

 

--For 單例項

SQL> oradebug hanganalyze 3;

Hang Analysis in /u01/app/oracle/admin/rac/udump/dave1_ora_20962.trc

 

這個命令會提示我們生成的trace 檔案。

 

--For RAC

SQL> oradebug setmypid

Statement processed.

SQL> oradebug setinst all

Statement processed.

SQL> oradebug -g def hanganalyze 3;

Hang Analysis in /u01/app/oracle/admin/rac/bdump/dave1_diag_32435.trc

 

檢視trace 檔案：

[oracle@rac1 u01]$ cat /u01/app/oracle/admin/rac/bdump/dave1_diag_32435.trc

/u01/app/oracle/admin/rac/bdump/dave1_diag_32435.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production

With the Partitioning, Real Application Clusters, OLAP and Data Mining options

ORACLE_HOME = /u01/app/oracle/product/10.2.0/db_1

System name:    Linux

Node name:      rac1

Release:        2.6.18-194.el5

Version:        #1 SMP Tue Mar 16 21:52:43 EDT 2010

Machine:        i686

Instance name: dave1

Redo thread mounted by this instance: 0

Oracle process number: 3

Unix process pid: 32435, image: oracle@rac1 (DIAG)

 

*** SERVICE NAME:() 2011-04-03 17:08:32.387

*** SESSION ID:(169.1) 2011-04-03 17:08:32.387

kjzcprt:rcv port created

Node id: 0

List of nodes: 0, 1,

*** 2011-04-03 17:08:32.388

Reconfiguration starts [incarn=0]

*** 2011-04-03 17:08:32.388

I'm the master node

A rcfg proposal from node 1 is received

*** 2011-04-03 17:08:33.439

Reconfiguration completes [incarn=14]

DIAG attached to DLM

cluster reconfiguration is ongoing: 0,

*** 2011-04-03 17:11:51.702

Reconfiguration starts [incarn=15]

*** 2011-04-03 17:11:51.702

I'm the master node

*** 2011-04-03 17:11:51.702

Reconfiguration completes [incarn=15]

Group reconfiguration cleanup

cluster reconfiguration is ongoing: 0, 1,

*** 2011-04-03 17:18:16.440

Reconfiguration starts [incarn=16]

*** 2011-04-03 17:18:16.440

I'm the master node

Group reconfiguration cleanup

A rcfg proposal from node 1 is received

*** 2011-04-03 17:18:17.245

Reconfiguration completes [incarn=16]

*** 2011-04-13 23:29:41.659

DIAG sends out oradebug command to nodes [0,1]

Switch to short timeout for ipc polling

a session (kjzddbx) is registered

********************************************************************

PORADEBUG BEGIN ORIGINATING INST:1 SERIAL:0 PID:20962

PORADATA COMMAND:hanganalyze 3

*** 2011-04-13 23:29:42.066

==============

HANG ANALYSIS: level 3 syslevel 1

==============

session (kjzddbx) switches to a new action

PORADATA TRACEFILE /u01/app/oracle/admin/rac/bdump/dave1_diag_32435.trc

PORADEBUG END ORIGINATING INST:1 SERIAL:0 PID:20962

********************************************************************

Open chains found:

Other chains found:

Chain 1 : :

    <0/125/52764/0x30e1dff4/20962/rdbms ipc reply>

Chain 2 : :

    <0/129/26/0x30e23580/4576/Streams AQ: qmn slave idle wait>

Chain 3 : :

    <0/130/16270/0x30e22fcc/4300/jobq slave wait>

Chain 4 : :

    <0/134/1/0x30e21eb0/669/Streams AQ: waiting for time man>

Chain 5 : :

    <0/138/11/0x30e21348/654/Streams AQ: waiting for messages>

Chain 6 : :

    <0/139/1/0x30e207e0/428/Streams AQ: qmn coordinator idle>

Chain 7 : :

    <0/169/1/0x30e16de4/32435/No Wait>

Chain 8 : :

    <1/130/14283/jobq slave wait>

Chain 9 : :

    <1/133/1/Streams AQ: qmn slave idle wait>

Chain 10 : :

    <1/134/1/Streams AQ: waiting for time man>

Chain 11 : :

    <1/139/1/Streams AQ: qmn coordinator idle>

Chain 12 : :

    <1/169/1/No Wait>

Extra information that will be dumped at higher levels:

[level  5] :  12 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]

[level 10] :  47 node dumps -- [IGN]

 

State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):

[123]/0/124/42982/0x30ee25bc/24834/IGN/1/2//none

[124]/0/125/52764/0x30ee3870/20962/SINGLE_NODE/3/4//none

[128]/0/129/26/0x30ee8340/4576/SINGLE_NODE/5/6//none

[129]/0/130/16270/0x30ee95f4/4300/SINGLE_NODE/7/8//none

[130]/0/131/2/0x30eea8a8/680/IGN/9/10//none

[131]/0/132/2/0x30eebb5c/663/IGN/11/12//none

[133]/0/134/1/0x30eee0c4/669/SINGLE_NODE/13/14//none

[137]/0/138/11/0x30ef2b94/654/SINGLE_NODE/15/16//none

[138]/0/139/1/0x30ef3e48/428/SINGLE_NODE/17/18//none

...

[168]/0/169/1/0x30f16f60/32435/SINGLE_NODE_NW/57/58//none

[169]/0/170/1/0x30f18214/32428/IGN/59/60//none

[295]/1/126/1125/0x30ee4b24//IGN/61/62//none

[299]/1/130/14283/0x30ee95f4//SINGLE_NODE/63/64//none

[302]/1/133/1/0x30eece10//SINGLE_NODE/65/66//none

[303]/1/134/1/0x30eee0c4//SINGLE_NODE/67/68//none

[305]/1/136/3/0x30ef062c//IGN/69/70//none

[306]/1/137/6/0x30ef18e0//IGN/71/72//none

[308]/1/139/1/0x30ef3e48//SINGLE_NODE/73/74//none

....

[337]/1/168/1/0x30f15cac//IGN/113/114//none

[338]/1/169/1/0x30f16f60//SINGLE_NODE_NW/115/116//none

[339]/1/170/1/0x30f18214//IGN/117/118//none

session (kjzddbx) switches to a new action

*** 2011-04-13 23:29:45.926

====================

END OF HANG ANALYSIS

====================

PORADATA SERIAL:0 RINST:2 RDIAG:8860

PORADATA SERIAL:0 RINST:2 REMOTE EXEC OSPID:8860

PORADATA SERIAL:0 RINST:2 TRACEFILE:/u01/app/oracle/admin/rac/bdump/dave2_diag_8860.trc

PORADATA SERIAL:0 RINST:2  DONE

session (kjzddbx) is about to end

session (kjzddbx) is about to end

Registered session (kjzddbx)[11][4][0][1] is cleaned up

Switch to long timeout for ipc polling

[oracle@rac1 u01]$

 

 

說明：

這個trace 檔案中最重要的部分是：

State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):

[123]/0/124/42982/0x30ee25bc/24834/IGN/1/2//none

[124]/0/125/52764/0x30ee3870/20962/SINGLE_NODE/3/4//none

[128]/0/129/26/0x30ee8340/4576/SINGLE_NODE/5/6//none

在上面的例項中的解釋如下：

 

nodenum：定義每個session的序列號

sid：session的sid

sess_srno：session的Serial＃

ospid：OS的程式ID

state：node的狀態

adjlist：表示blocker node

predecessor：表示waiter node

 

State有如下幾種狀態：

       （1）IN_HANG：如果Session處於這種狀態，表示Session遇到deadlock或者處於hung狀態。

       （2）LEAF/LEAF_NW：這些Session通常是“blocker”或者是等待某些資源的“slow” node，通過欄位“predecessor” 可以很容易標識出這些node。

       （3）NLEAF：這些Session通常被認為是“stuck”會話，意味著這些Session在等待某些Session的資源。通過欄位“adjlist”可以很容易的定義該程式的blocker。

       （4）IGN/IGN_DMP：這些Session通常是IDLE Session。

 

 

 

四.  官網的一個說明示例

       因為我的環境沒有一個詳細的環境，所以在官網找了一個完整點的示例說明。 對照這些說明，看的比較清楚。

 

 

==============
HANG ANALYSIS:
==============

CYCLES: This section reports the process dependencies between sessions that are in a deadlock condition. Cycles are considered   “true” hangs.

Cycle 1 : :

    <980/3887/0xe4214964/24065/latch free>

 -- <2518/352/0xe4216560/24574/latch free>

 -- <55/10/0xe41236a8/13751/latch free>

BLOCKER OF MANY SESSIONS: This section is found when a process is blocking a lot of other sessions. Usually when a process is blocking more that 10 sessions this section will appear in the trace file.

Found 21 objects waiting for

    <55/10/0xe41236a8/13751/latch free>

Found 12 objects waiting for

    <2098/2280/0xe42870d0/3022/db file scattered read>

Found 12 objects waiting for

    <1941/1783/0xe41ac9e0/462/No Wait>

Found 12 objects waiting for

    <980/3887/0xe4214964/24065/latch free>

OPEN CHAINS: This section reports sessions involved on a wait chain. A wait chains means that one session is blocking one or more other sessions.

Open chains found:
Chain 1 : :

    <2/1/0xe411b0f4/12280/db file parallel write>

Chain 2 : :

    <3/1/0xe411b410/12282/No Wait>

Chain 6 : :

    <18/1631/0xe4243cf8/25457/db file scattered read>

 -- <229/1568/0xe422b84c/8460/buffer busy waits>

Chain 17 : :

    <56/11/0xe4123ce0/13755/latch free>

 -- <2384/599/0xe41890dc/22488/latch free>

 -- <32/2703/0xe41fa284/25693/latch free>

OTHER CHAINS: It refers to chains of blockers and waiters related to other sessions identified under “open chains”, but not blocked directly by the process reported on the "open chain". 

Other chains found:
Chain 676 : :

    <20/93/0xe411d644/13597/latch free>

Chain 677 : :

    <27/1201/0xe41d3188/15809/latch free>

Chain 678 : :

    <36/1532/0xe428be8c/4232/latch free>

 -- <706/1216/0xe4121aac/23317/latch free>

Chain 679 : :

    <43/12/0xe4122d54/13745/latch free>

Chain 680 : :

    <80/2/0xe41290d4/13811/library cache pin>

 -- <1919/1134/0xe421fdbc/3343/enqueue>

Additional DUMP detail: HANGANALYZE generates errorstack dumps for individual processes based on: the LEVEL used when the command is issued, and the STATE of the session. This part of the HANGANALYZE trace indicates which processes will be dumped if higher levels are used. It also indicates how many nodes will be dumped so you can measure the impact to the system (if too many errorstack dumps occur simultaneously, the disks serving the trace destination may become saturated). The “STATE DESCRIPTION” section of this document further explains the meaning of the states.

Extra information that will be dumped at higher levels:
[level  4] :  23 node dumps -- [LEAF] [LEAF_NW] [IGN_DMP]
[level  5] :  36 node dumps -- [NLEAF]
[level 10] : 130 node dumps -- [IGN]

STATE OF NODES: This section might be considered as the main section of the report. It shows all the sessions connected when the HANGANALYZE trace file was generated. This section essentially describes a dependency graph between nodes(known as an “adjacency list”), where each session is considered a node, and each node may have an “adjacent” node or a “predecessor” node related to it. Depending on the state of the node it may be a blocker, a waiter or a hung node. The “STATE DESCRIPTION” section of this document explains further the meaning of the states.

State of nodes

([nodenum]/sid/sess_srno/session/state/start/finish/[adjlist]/predecessor):

[0]/1/1/0xa6f8b0/IGN/1/2//none

[1]/2/1/0xa70230/IGN/3/4//none

[3]/4/1/0xa71530/IGN/5/6//none

[4]/5/1/0xa71eb0/IGN/7/8//none

[5]/6/1/0xa72830/IGN/9/10//none

[6]/7/1/0xa731b0/IGN/11/12//none

[7]/8/1/0xa73b30/IGN/13/14//none

[8]/9/1/0xa744b0/IGN_DMP/15/18/[130]/none

[9]/10/1/0xa74e30/IGN/19/20//none

[10]/11/4202/0xa757b0/IGN/21/22/[130]/none

[11]/12/1196/0xa76130/NLEAF/23/28/[49]/none

[12]/13/1/0xa76ab0/IGN/29/30/[130]/none

[37]/38/37/0xa85830/NLEAF/73/76/[50]/46

[46]/47/15/0xa8adb0/NLEAF/91/92/[37][50]/none

====================

END OF HANG ANALYSIS

====================

 

以上是對TRACE 中的分段資訊的說明。 下面是對每個node 的state的說明：

 

 

STATE OF THE NODES DESCRIPTION

  As described before, HANGANALYZE use the model of “Adjacency Lists” to report the sessions found when the HANGANALYZE command was issued. In Graph Theory, an adjacency list represents a list of nodes that are connected to a given node. For each node, a linked list of nodes connected to it can be set up to represent the neighbor node connected. To be able to interpret a HANGANALYZE trace file it is required to relate the “STATE” of the node with the “adjacent” node to it.
A typical entry in the state of the nodes section will be as follow:

Oracle 8.x : [nodenum]/sid/sess_srno/session/state/start/finish/[adjlist]/predecessor
Oracle9i: [nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor

Where:
 Nodenum     = This is sequential number used by HANGANALYZE to identify each session
 sid         = Session ID
 sess_srno   = Serial#
 ospid        = OS Process Id
 state       = State of the node
 adjlist     = adjacent node   (Usually represents a  blocker node)
 predecessor = predecessor node (Usually represents a waiter node)
 cnode        = Node number (Only available since Oracle9i)

The following describes the important states to be considered:

IN_HANG: This might be considered as the most critical STATE. Basically a node in this state is involved in a deadlock, or is hung. Usually there will be another “adjacent node” in the same status. For example:

 [nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
 [16]/0/17/154/0x24617be0/26800/IN_HANG/29/32/[185]/19
 [185]/1/16/4966/0x24617270//IN_HANG/30/31/[16]/16

In this example the node [16] is waiting for node [185], and the other way around; this is  a cyclical condition (deadlock).
 

LEAF and LEAF_NW: Leaf nodes are considered on top of the wait chain (usually blockers). They are considered “Blockers” when there is another session waiting. This can be easily identified using the “predecesor” field. If there is a node referenced in the ‘prdecessor’ field, the node is considered as “blocker”, otherwise it is considered as a “slow” session waiting for some resource.
The difference between LEAF and LEAF_NW is that LEAF nodes are not waiting for something, while LEAF_NW are not waiting or may be using the CPU. A typical representation of these nodes when they are considered blockers is:

 [ nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
 [16]/0/17/154/0x24617be0/26800/LEAF/29/30//19
 [19]/0/20/13/0x24619830/26791/NLEAF/33/34/[16]/186

In this example, node [16] is blocking node [19]. Notice that node [16] has node [19] in the predecessor field.
Also notice that node [19] has node [16] in the adjacent list.
 

NLEAF : These sessions are usually considered as “stuck” sessions. It means that there is another session holding a resource needed by the session in this state. By using the adjlist, you can determine which node is the blocker of this process. When many sessions are found in this state, it is likely the database is experiencing a performance problem rather than a hang problem.

 

IGN and IGN_DMP : Sessions in this state are usually considered as IDLE sessions, unless they reference a node in the “ adjlist” field. In this case, the node is waiting for another node, so it will be considered as a ‘stuck’ session as well.
Extending the previous example,

 [nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
 [16]/0/17/154/0x24617be0/26800/LEAF/29/30//19
 [19]/0/20/13/0x24619830/26791/NLEAF/33/34/[16]/186
 [189]/1/20/36/0x24619830//IGN/95/96/[19]/none
 [176]/1/7/1/0x24611d80//IGN/75/76//none

       You may notice that node [189] is waiting for node [19] which in turn is waiting for node [16], while node [176] is an IDLE session . This maybe the case when a session has a DML lock but never finished the transaction. 

In Oracle9i, two new states were introduced to differentiate between LEAF nodes that have other nodes waiting behind them (i.e., LEAF nodes that are blockers) vs. LEAF nodes that are not affecting other nodes.
 

SINGLE_NODE and SINGLE_NODE_NW:
       This can be described the same as LEAF and LEAF_NW, except that they don't have processes depending on them.
 

LEVEL USAGE RECOMMENDATIONS

       It is advisable not to use levels higher than 3 due to the potentially large number of trace files that may be produced (and could overwhelm the I/O subsystem). Since HANGANALYZE will be mostly used to diagnose “true hangs”, a level 3 will dump the processes that are involved in a the hang condition – this usually involves fewer than 4 processes.

-- 不要超過level 3
       Level 4 may be used with caution when dealing with performance scenarios where sessions are being stuck for a long period of time, and no other information can be gathered. Be carefull that a HANGANALYZE level 4 will dump all the processes in the following states:
       [LEAF] [LEAF_NW] [IGN_DMP]. Before doing so, perform a HANGANALYZE level 3, and check the section: “Extra information that will be dumped at higher levels”. This section will tell you exactly how many sessions will be dumped at each level.   It is diffucult to know how many dumps are an acceptable number to keep from saturating the disks due to the differences in disk implementations (5 to 10 is probably OK for most systems; larger systems may be able to handle 20 to 40 dumps).  

 

       Level 5 and 10 are typicaly useless and generate a huge amount of trace files that may severely impact the performance of the database.