技術ブログ
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から読みやすさの点でかなり強化されています。 この点について触れている情報が意外とないので簡単に紹介します。
ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level 3';を実行してください。トレースファイルに診断情報が出力されます。
まず、古い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 ====================
=============================================================================== 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年前なんですね・・・ 時の流れは速い・・・。
プロフィール
渡部 亮太
・Oracle ACE
・AWS Certified Solutions Architect - Associate
・ORACLE MASTER Platinum Oracle Database 11g, 12c 他多数
カテゴリー
アーカイブ
2024年
2023年
2022年
2021年
2020年
2019年
2018年
2017年
2016年
2015年
2014年
2013年
2012年
2000年