株式会社コーソル

コーソルDatabaseエンジニアのブログ

技術ブログ

Oracle Database 11g HANG ANALYZE診断情報の強化

Excelを用いたASH分析方法の紹介とdb tech showcase 大阪 2013セッション担当のお知らせ に引き続き、db tech showcase 大阪 2013で担当させていただく"Analyzing Oracle Database hang issues using various diagnostics."のセッション内容に関連するエントリです。

"Analyzing Oracle Database hang issues using various diagnostics." では ハング事象におけるもっとも有効な診断情報として、HANG ANALYZE をご紹介します。 12c Databaseがリリースされようとしている昨今では、かなりイマサラ感がありますが・・・ このHANG ANALYZEは、Oracle Database 11.1から読みやすさの点でかなり強化されています。 この点について触れている情報が意外とないので簡単に紹介します。

HANG ANALYZEの取得方法

sysユーザーで
ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level 3';
を実行してください。トレースファイルに診断情報が出力されます。

10.2.0.5のHANG ANALYZE

まず、古いHANG ANALYZEは以下のような感じです。 待機チェーンの情報が記載されてますが、直観的に理解しやすいとは言えません。 例えば、"sid","ospid"としてセッションIDやOS プロセスIDが記載されていますが、 これらがどのようなセッションなのか、どのようなプロセスなのかが記載されていない ため、別の情報にあたって調べる必要があります。

==============
HANG ANALYSIS:
==============
Open chains found:
Chain 1 :  :
    <0/159/5/0x7d66ef90/3710/No Wait>
 -- <0/155/1/0x7d66ff80/3700/enq: CF - contention>
Other chains found:
Chain 2 :  :
    <0/141/1/0x7d674f30/3732/No Wait>
Chain 3 :  :
    <0/143/24/0x7d672758/3758/rdbms ipc reply>
Chain 4 :  :
    <0/150/19/0x7d671768/3751/jobq slave wait>
Chain 5 :  :
    <0/151/4/0x7d671f60/3714/Streams AQ: qmn slave idle wait>
Chain 6 :  :
    <0/153/1/0x7d670778/3702/Streams AQ: qmn coordinator idle>
Chain 7 :  :
    <0/158/9/0x7d670f70/3712/Streams AQ: waiting for time man>
Chain 8 :  :
    <0/165/1/0x7d66afd0/3679/enq: CF - contention>
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW] 
[level  5] :   6 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP] 
[level  6] :   2 node dumps -- [NLEAF] 
[level 10] :  11 node dumps -- [IGN] 

State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[140]/0/141/1/0x7d778100/3732/SINGLE_NODE_NW/1/2//none
[142]/0/143/24/0x7d77abf0/3758/SINGLE_NODE/3/4//none
[149]/0/150/19/0x7d784238/3751/SINGLE_NODE/5/6//none
[150]/0/151/4/0x7d7857b0/3714/SINGLE_NODE/7/8//none
[152]/0/153/1/0x7d7882a0/3702/SINGLE_NODE/9/10//none
[154]/0/155/1/0x7d78ad90/3700/NLEAF/11/14/[158]/none
[155]/0/156/1/0x7d78c308/3698/IGN/15/16//none
[157]/0/158/9/0x7d78edf8/3712/SINGLE_NODE/17/18//none
[158]/0/159/5/0x7d790370/3710/LEAF_NW/12/13//154
[159]/0/160/1/0x7d7918e8/3687/IGN/19/20//none
[160]/0/161/1/0x7d792e60/3689/IGN/21/22//none
[161]/0/162/1/0x7d7943d8/3685/IGN/23/24//none
[162]/0/163/1/0x7d795950/3683/IGN/25/26//none
[163]/0/164/1/0x7d796ec8/3681/IGN/27/28//none
[164]/0/165/1/0x7d798440/3679/NLEAF/29/30/[158]/none
[165]/0/166/1/0x7d7999b8/3677/IGN/31/32//none
[166]/0/167/1/0x7d79af30/3675/IGN/33/34//none
[167]/0/168/1/0x7d79c4a8/3671/IGN/35/36//none
[168]/0/169/1/0x7d79da20/3673/IGN/37/38//none
[169]/0/170/1/0x7d79ef98/3669/IGN/39/40//none
====================
END OF HANG ANALYSIS
====================

11.1.0.7のHANG ANALYZE

11.1.0.7のHANG ANALYZEは以下のようです。 待機チェーンにつながっているセッションやプロセスの状態("Oracle session identified by"の箇所) や、待機の状態("is waiting for '...' with wait info:の"箇所)が分かりやすく 出力されていることがわかります。
===============================================================================
HANG ANALYSIS:
  instances (db_name.oracle_sid): b107.b107
  oradebug_node_dump_level: 3
===============================================================================

Chains most likely to have caused the hang:
 [a] Chain 1 Signature: <='enq: CF - contention'<='rdbms ipc reply'
     Chain 1 Signature Hash: 0x1daff9a4
 [b] Chain 2 Signature: <='enq: CF - contention'
     Chain 2 Signature Hash: 0xdc9297cc

===============================================================================
Non-intersecting chains:

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (b107.b107)
                   os id: 3154
              process id: 31, oracle@l54x64a.domain (TNS V1-V3)
              session id: 131
        session serial #: 7
    }
    is waiting for 'rdbms ipc reply' with wait info:
    {
                      p1: 'from_process'=0xb
                      p2: 'timeout'=0x147ae06
            time in wait: 1.892141 sec
           timeout after: 0.107859 sec
                 wait id: 417
                blocking: 0 sessions
            wait history:
              1.     event: 'rdbms ipc reply'
                   wait id: 416             p1: 'from_process'=0xb
               time waited: 1.999876 sec    p2: 'timeout'=0x147ae08
              2.     event: 'rdbms ipc reply'
                   wait id: 415             p1: 'from_process'=0xb
               time waited: 2.000048 sec    p2: 'timeout'=0x147ae0a
              3.     event: 'rdbms ipc reply'
                   wait id: 414             p1: 'from_process'=0xb
               time waited: 1.999949 sec    p2: 'timeout'=0x147ae0c
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (b107.b107)
                   os id: 3067
              process id: 11, oracle@l54x64a.domain (CKPT)
              session id: 160
        session serial #: 1
    }
    which is waiting for 'enq: CF - contention' with wait info:
    {
                      p1: 'name|mode'=0x43460004
                      p2: '0'=0x0
                      p3: 'operation'=0x0
            time in wait: 15.890536 sec
           timeout after: 14 min 44 sec
                 wait id: 1918
                blocking: 1 session
            wait history:
              1.     event: 'rdbms ipc message'
                   wait id: 1917            p1: 'timeout'=0x12c
               time waited: 2.327902 sec    
              2.     event: 'control file sequential read'
                   wait id: 1916            p1: 'file#'=0x0
               time waited: 0.000042 sec    p2: 'block#'=0x3
                                            p3: 'blocks'=0x1
              3.     event: 'control file parallel write'
                   wait id: 1915            p1: 'files'=0x3
               time waited: 0.002068 sec    p2: 'block#'=0x3
                                            p3: 'requests'=0x3
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (b107.b107)
                   os id: 3118
              process id: 18, oracle@l54x64a.domain (TNS V1-V3)
              session id: 170
        session serial #: 7
    }
    which is not in a wait:
    {
               last wait: 1 min 18 sec ago
                blocking: 3 sessions
            wait history:
              1.     event: 'SQL*Net message from client'
                   wait id: 126             p1: 'driver id'=0x62657100
               time waited: 14 min 16 sec   p2: '#bytes'=0x1
              2.     event: 'SQL*Net message to client'
                   wait id: 125             p1: 'driver id'=0x62657100
               time waited: 0.000007 sec    p2: '#bytes'=0x1
              3.     event: 'control file sequential read'
                   wait id: 124             p1: 'file#'=0x0
               time waited: 0.000031 sec    p2: 'block#'=0x16
                                            p3: 'blocks'=0x1
    }

Chain 1 Signature: <='enq: CF - contention'<='rdbms ipc reply'
Chain 1 Signature Hash: 0x1daff9a4
-------------------------------------------------------------------------------

===============================================================================
Intersecting chains:

-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (b107.b107)
                   os id: 3090
              process id: 20, oracle@l54x64a.domain (ARC1)
              session id: 152
        session serial #: 2
    }
    is waiting for 'enq: CF - contention' with wait info:
    {
                      p1: 'name|mode'=0x43460004
                      p2: '0'=0x0
                      p3: 'operation'=0x0
            time in wait: 47.138856 sec
           timeout after: 14 min 12 sec
                 wait id: 482
                blocking: 0 sessions
            wait history:
              1.     event: 'rdbms ipc message'
                   wait id: 481             p1: 'timeout'=0x1770
               time waited: 1 min 0 sec     
              2.     event: 'control file sequential read'
                   wait id: 480             p1: 'file#'=0x0
               time waited: 0.000012 sec    p2: 'block#'=0x14
                                            p3: 'blocks'=0x1
              3.     event: 'control file sequential read'
                   wait id: 479             p1: 'file#'=0x0
               time waited: 0.000015 sec    p2: 'block#'=0x16
                                            p3: 'blocks'=0x1
    }
    and is blocked by 'instance: 1, os id: 3118, session id: 170',
    which is a member of 'Chain 1'.

Chain 2 Signature: <='enq: CF - contention'
Chain 2 Signature Hash: 0xdc9297cc
-------------------------------------------------------------------------------

===============================================================================
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
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[130]/1/131/7/0x6c945388/3154/NLEAF/[159]
[151]/1/152/2/0x6c97e070/3090/NLEAF/[169]
[159]/1/160/1/0x6c993ab0/3067/NLEAF/[169][151]
[169]/1/170/7/0x6c9aeb80/3118/LEAF_NW/

*** 2011-11-17 19:34:44.510
===============================================================================
END OF HANG ANALYSIS
===============================================================================

などと書きながらふと思ったのですが、Oracle Database 11gがリリースされたのって 2007年、もう6年前なんですね・・・ 時の流れは速い・・・。

プロフィール

On7tWW6m1Ul4

渡部 亮太

・Oracle ACE
・AWS Certified Solutions Architect - Associate
・ORACLE MASTER Platinum Oracle Database 11g, 12c 他多数

カテゴリー

アーカイブ