本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳：渡部 亮太 (WR at Csus4 dot net)
履歴
- 2013-12-18: 初稿up
Advanced Oracle Troubleshooting Guide – Part 11 ：ash_wait_chains.sqlを用いた複雑な待機チェーンのシグネチャ分析
ここに、ハードコアOracleパフォーマンスオタクのための御馳走がある – クールであるが、まだ実験的なASH（またはpoor-man's ASH）ベースの待機イベント分析のためのスクリプトをリリースする。これは、ASHベースのパフォーマンス分析に全く新しい次元を追加するだろう。これは、既存のASH分析テクニックのいずれかを置き換えるものではありませんが、以前よりもはるかに簡単に、複雑な待機チェーンに含まれるOracleセッションの関係を明らかにする《bright daylight》。
みなさんは、以下のAWR/Statspackの時間を要した《待機》イベントのサマリに精通している《でしょう》。
これに似たブレークダウンは、待機イベントでASHサンプルを単に集約することによって得ることができます。
SQL> @ash/dashtop session_state,event 1=1 "TIMESTAMP'2013-09-09 21:00:00'" "TIMESTAMP'2013-09-09 22:00:00'"
%This SESSION EVENT TotalSeconds CPU User I/O Application Concurrency Commit Configuration Cluster Idle Network System I/O Scheduler Administrative Queueing Other MIN(SAMPLE_TIME) MAX(SAMPLE_TIME)
\------ ------- ---------------------------------------------------------------- ------------ ---------- ---------- ----------- ----------- ---------- ------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- --------------------------------------------------------------------------- ---------------------------------------------------------------------------
68% ON CPU 25610 25610 0 0 0 0 0 0 0 0 0 0 0 0 0 09-SEP-13 09.00.01.468 PM 09-SEP-13 09.59.58.059 PM
14% WAITING SQL\*Net more data from client 5380 0 0 0 0 0 0 0 0 5380 0 0 0 0 0 09-SEP-13 09.00.01.468 PM 09-SEP-13 09.59.58.059 PM
6% WAITING enq: HW - contention 2260 0 0 0 0 0 2260 0 0 0 0 0 0 0 0 09-SEP-13 09.04.41.893 PM 09-SEP-13 09.56.07.626 PM
3% WAITING log file parallel write 1090 0 0 0 0 0 0 0 0 0 1090 0 0 0 0 09-SEP-13 09.00.11.478 PM 09-SEP-13 09.59.58.059 PM
2% WAITING db file parallel write 730 0 0 0 0 0 0 0 0 0 730 0 0 0 0 09-SEP-13 09.01.11.568 PM 09-SEP-13 09.59.48.049 PM
2% WAITING enq: TX - contention 600 0 0 0 0 0 0 0 0 0 0 0 0 0 600 09-SEP-13 09.04.41.893 PM 09-SEP-13 09.48.16.695 PM
1% WAITING buffer busy waits 560 0 0 0 560 0 0 0 0 0 0 0 0 0 0 09-SEP-13 09.10.02.492 PM 09-SEP-13 09.56.07.626 PM
1% WAITING log file switch completion 420 0 0 0 0 0 420 0 0 0 0 0 0 0 0 09-SEP-13 09.47.16.562 PM 09-SEP-13 09.47.16.562 PM
1% WAITING latch: redo allocation 330 0 0 0 0 0 0 0 0 0 0 0 0 0 330 09-SEP-13 09.04.41.893 PM 09-SEP-13 09.53.27.307 PM
...
上記の出力は、マルチユーザー（データベース）システムでは1つの欠点を持っています – すべての待機イベントが、OSが（IO要求のような）いくつかの自己完結型の操作の完了させるのをセッションが待機するような、単純なものではない。多くの場合、セッションは（いくつかのロックを保持している） 別のセッション、または、セッションを続行する前にいくつかのタスクを完了する必要があるバックグラウンドプロセスを待機しています。
その、他のセッションは、ロックのため、またさらに別のセッションを待っているかもしれません。他のセッション自体は、いくつかのバッファピンのため（(buffer busy wait）のため、さらに別のセッションを待っています。バッファピンを保持しているセッションは、LGWRを待っているかもしれません。それは、DBWRなどを待っているかもしれません。わかりましたね。 – 待っていることが…あなたはポイントを得る – 時々、チェーンのようにお互いを待つ一連のセッションがあります。
Oracle 11gで導入されたV$WAIT_CHAINSビューは、待機中のセッションのような鎖を示すことが可能である。 – しかし、それはパフォーマンスの問題と短い（しかし、非自明な）競合をではなく、比較的長く持続するハングを診断するために設計されています。パフォーマンスの問題と短い（しかし、非自明な）競合をパフォーマンスの問題と短い（しかし、非自明な）競合を数秒待機した後では、チェーンを歩き、V$WAIT_CHAIN??S《に値を移入する》ことを担当するDIAGプロセスは数秒ではキックしません。このため、V$WAIT_CHAIN??Sビューは、ほとんどが空の場合があります – パフォーマンス分析のために別のものが必要です。
さて、そのセッションをやっていたものを見ると-今、それは待機セッションの1つを選んで、ブロックするSIDを検索するためにblocking_session列を使用することが可能である。私は少しこれを手動で行ったことがある。しかし、いくつかのASHサンプル反復トリックとともに、シンプルなCONNECT BYループ《をつかうこと》では簡単複雑な待機チェーンサイン ＆階層情報を得られることに気づきました。
だから、あなた方に新しいash_wait_chains.sqlのスクリプトをお見せしたい！（Woo-hoo!）。現時点では完全に実験的であり、正しい結果を返すことはまったく保障されません。また、計画中の一部の構文はまだ実装されていません:-) 実験的なんです。ベータですらありません。:-) そして、RACもDBA_HIST ASHも、まだサポートしていません。
下の例では、ASHビューにおいて単に疑似列に過ぎないEVENT2（をパラメータに指定して、スクリプトを実行しています。だから、チェーンに関わるセッションの待機イベントだけを示しています。あなたは、プログラム、モジュール、sql_opnameなどのような、追加の情報のために、そこに任意のASH列を指定できます。
SQL> @ash/ash_wait_chains event2 1=1 sysdate-1 sysdate
-- ASH Wait Chain Signature script v0.1 EXPERIMENTAL by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS WAIT_CHAIN
\------ ---------- ------------------------------------------------------------------------------------------
60% 77995 -> ON CPU
10% 12642 -> cell single block physical read
9% 11515 -> SQL\*Net more data from client
2% 3081 -> log file parallel write
2% 3073 -> enq: HW - contention -> cell smart file creation
2% 2723 -> enq: HW - contention -> buffer busy waits -> cell smart file creation
2% 2098 -> cell smart table scan
1% 1817 -> db file parallel write
1% 1375 -> latch: redo allocation -> ON CPU
1% 1023 -> enq: TX - contention -> buffer busy waits -> cell smart file creation
1% 868 -> block change tracking buffer space
1% 780 -> enq: TX - contention -> buffer busy waits -> ASM file metadata operation
1% 773 -> latch: redo allocation
1% 698 -> enq: TX - contention -> buffer busy waits -> DFS lock handle
0% 529 -> enq: TX - contention -> buffer busy waits -> control file parallel write
0% 418 -> enq: HW - contention -> buffer busy waits -> DFS lock handle
上の出力には、私たちに何を教えていますか？私は上記の3行を強調している。enq:HW – contention待機イベントについてより詳細な洞察を取得したいとしましょう。ash_wait_chainsスクリプトは、単に単一の待機イベント名《を表示する》代わりに、
"複雑な"待機チェーンのシグネシャ（誰が誰のために待っている）により、待機イベントをブレークダウンする！左から右に待機チェーンの情報をお読みください。例えば、分析されたASHデータセットの合計応答時間（3073秒）の2％が 、HWエンキュー を待機するセッションで費やされた。《そのHWエンキューは、》cell smart file creationを待っている別のセッションにより保持されている。右端の待機イベントが、 「究極のブロッカー」である。残念ながら、ASHは、デフォルトでアイドル状態のセッションをキャプチャしていない（アイドルセッションがロックを保持し、他の人をブロックしている可能性がある）ので、このスクリプトの現在のバージョン（0.1）で、アイドル状態のブロッカーは出力から欠落しています。後で見るように、しかし手動で不足している/アイドルセッションを検出できます。
したがって、このスクリプトでは、単一の「スカラー」イベントだけではなく、
待機セッションのチェーン全体におけるすべての待機イベント（および他の属性） から、ASH待機データを分析できます。 – ボトルネックにおける階層や依存情報を明らかにする！様々なバックグラウンド?プロセスに関連するチェーンを調査している場合は特に、我々は、Oracleインスタンス内のプロセス?フローに興味深い洞察を得る。
出力に任意のASH列を追加することができる（長くないのでスクリプトを見てみてください）ので、program情報を追加してみましょう。すると、複雑な待機に関与していたセッションの種類を知られるでしょう。（私は出力からさほど興味深くない行を削除し、いくつかの興味深い行をハイライトした）。もう一度、左から右にウェイターのチェーンを読んでね 
SQL> @ash/ash_wait_chains program2||event2 1=1 sysdate-1 sysdate
-- ASH Wait Chain Signature script v0.1 EXPERIMENTAL by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS WAIT_CHAIN
\------ ---------- -----------------------------------------------------------------------------------------------------------------------------------------------
56% 73427 -> (JDBC Thin Client) ON CPU
9% 11513 -> (JDBC Thin Client) SQL\*Net more data from client
9% 11402 -> (oracle@enkxndbnn.enkitec.com (Jnnn)) cell single block physical read
2% 3081 -> (LGWR) log file parallel write
2% 3073 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) cell smart file creation
2% 2300 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (JDBC Thin Client) cell smart file creation
...
1% 1356 -> (JDBC Thin Client) latch: redo allocation -> (JDBC Thin Client) ON CPU
1% 1199 -> (JDBC Thin Client) cell single block physical read
1% 1023 -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) cell smart file creation
1% 881 -> (CTWR) ON CPU
1% 858 -> (JDBC Thin Client) block change tracking buffer space
1% 780 -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) ASM file metadata operation
1% 766 -> (JDBC Thin Client) latch: redo allocation
1% 698 -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) DFS lock handle
0% 529 -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) control file parallel write
0% 423 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) cell smart file creation
0% 418 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) ASM file metadata operation
0% 418 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) DFS lock handle
...
0% 25 -> (JDBC Thin Client) gcs drm freeze in enter server mode -> (LMON) ges lms sync during dynamic remastering and reconfig -> (LMSn) ON CPU
0% 25 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) DFS lock handle -> (DBWn) db file parallel write
...
0% 18 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) CSS operation: action
0% 18 -> (LMON) control file sequential read
0% 17 -> (LMSn) ON CPU
0% 17 -> (JDBC Thin Client) buffer busy waits -> (Wnnn) cell smart file creation
0% 16 -> (JDBC Thin Client) enq: FB - contention -> (JDBC Thin Client) gcs drm freeze in enter server mode -> (LMON) ges lms sync during dynamic remastering and reconfig -> (LMSn) ON CPU
...
0% 3 -> (JDBC Thin Client) enq: HW - contention -> (JDBC Thin Client) buffer busy waits -> (JDBC Thin Client) CSS operation: action
0% 3 -> (JDBC Thin Client) buffer busy waits -> (JDBC Thin Client) latch: redo allocation -> (JDBC Thin Client) ON CPU
...
0% 1 -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) enq: TX - contention -> (JDBC Thin Client) buffer busy waits -> (Wnnn) ASM file metadata operation
0% 1 -> (Wnnn) buffer busy waits -> (JDBC Thin Client) block change tracking buffer space
...
別の例では、sql_opname 列（11.2以降）を追加すると、ロック競合の分析に有用である、待機により終わってしまった（UPDATE, DELETE, LOCKなどのような）SQLコマンドの種類を表示できます。
SQL> @ash/ash_wait_chains sql_opname||':'||event2 1=1 sysdate-1/24/60 sysdate
\-- Display ASH Wait Chain Signatures script v0.1 EXPERIMENTAL by Tanel Poder ( http://blog.tanelpoder.com )
%This ? ? SECONDS WAIT_CHAIN
\------ ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------
? 18% ? ? ? ? ?45 -> LOCK TABLE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention
? 18% ? ? ? ? ?45 -> LOCK TABLE:enq: TM - contention
? 17% ? ? ? ? ?42 -> DELETE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention
? 10% ? ? ? ? ?25 -> SELECT:direct path read
? ?6% ? ? ? ? ?14 -> TRUNCATE TABLE:enq: TM - contention
? ?5% ? ? ? ? ?13 -> SELECT:ON CPU
? ?2% ? ? ? ? ? 5 -> LOCK TABLE:enq: TM - contention ?-> SELECT:ON CPU
? ?2% ? ? ? ? ? 5 -> TRUNCATE TABLE:enq: TM - contention ?-> SELECT:ON CPU
? ?2% ? ? ? ? ? 5 -> SELECT:db file scattered read
? ?2% ? ? ? ? ? 5 -> DELETE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:db file scattered read
? ?2% ? ? ? ? ? 5 -> DELETE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:ON CPU
? ?2% ? ? ? ? ? 5 -> LOCK TABLE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:db file scattered read
? ?2% ? ? ? ? ? 5 -> TRUNCATE TABLE:enq: TM - contention ?-> SELECT:db file scattered read
? ?2% ? ? ? ? ? 5 -> LOCK TABLE:enq: TM - contention ?-> SELECT:db file scattered read
? ?2% ? ? ? ? ? 5 -> LOCK TABLE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:ON CPU
? ?2% ? ? ? ? ? 4 -> TRUNCATE TABLE:enq: TM - contention ?-> SELECT:direct path read
? ?2% ? ? ? ? ? 4 -> LOCK TABLE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:direct path read
? ?2% ? ? ? ? ? 4 -> DELETE:enq: TM - contention ?-> LOCK TABLE:enq: TM - contention ?-> SELECT:direct path read
? ?2% ? ? ? ? ? 4 -> LOCK TABLE:enq: TM - contention ?-> SELECT:direct path read
これは実験的なスクリプトで、今いくつかの問題や欠点を持っています。最終的なブロッキングセッションがサンプリング中にアイドル状態だった場合、上記で青にハイライトした行のように、ブロッキングセッションは表示されない。 – ASHはアイドルセッションのサンプルを捕捉しないので。また、それは、現在はRACに対しては機能しない（RACにおけるglobal待機イベントに対するblocking_session情報は、インスタンスローカルの場合とは異なり、すぐに解決できないので、これが問題になるかもしれません）。そして、このテクニックの活用を説明する良い例を探すつもりです。(私は、あなたがビジーなデータベースの分析結果を送ってくれることを歓迎しています:-) )
2013年10月/11月に再びAdvanced Oracle Troubleshootingクラスを行うことに注意してください。今あなたがより多くのクールな（そしてさらに便利な）Oracleのトラブルシューティングstuffを学ぶ場所を知る★