本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳：渡部 亮太 (WR at Csus4 dot net)
履歴
- 2013-12-22: 初稿up
ash_wait_chains.sqlスクリプト（v0.2）でbuffer busy waitsを診断する
私の以前の記事（ Advanced Oracle Troubleshooting Guide – Part 11 ：ash_wait_chains.sqlを用いた複雑な待機チェーンのシグネチャ分析 ）では、「上位ASH待機チェーン」の視点から、パフォーマンスを分析するための実験的なスクリプトを導入しました。スクリプトの初期バージョン（0.1）は、分析のために、特定のユーザ（セッション）、SQLまたはモジュール/アクションのパフォーマンス?データを選択《フィルタ、SELECT》する機能を持っていませんでした。（ブロッキングセッションは、任意のユーザから来る可能性があるので）、このためのSQLを記述する方法を考え出していなかった。そして、connect by ループにおいて、「START WITH <条件>」を使うだけ、だったことがわかった。さあ、スクリプトの（誰の活動を測定するための）パラメータ 2は、実際に動作します。
最新バージョンをダウンロードしてください。
- ash_wait_chains.sql （V$ACTIVE_SESSION_HISTORYデータでASHの待機チェーンを分析）
- dash_wait_chains.sql （DBA_HIST_ACTIVE_SESS_HISTORYデータでASHの待機チェーンを分析）
では、実際にパラメータ#2を使います。《使ってみます》、たとえば、以下のusername='TANEL'構文は、トップレベルのウェイターとしてのTanelのセッションだけを一覧表示することを意味します。しかし、もちろん、他のユーザーのセッションによりTanelのセッションがブロックされているかもしれないので、このwhere句は、usernameにかかわらず、どんなブロッカーも表示を制限しません《where句がブロッカーをフィルタすることはないということ》。
@ash_wait_chains program2||event2 username='TANEL' sysdate-1/24 sysdate
私は1つ以上の改善を追加しました。すぐにそれを見るでしょう。さて、ある問題の例がここにあります。私は（Exadataの上で）HadoopからOracleへ1TBの「表」を並列ロードするパフォーマンステストを行っていた。私は（HadoopのSQLコネクタを使った）外部表を使用していた。ここに、SQL監視レポートのアクティビティをしめすチャートがあります。
応答時間の大部分は、 buffer busy waitsの待機に費やされました！そして、チェックするための通常のステップは、以下の通りです。
- 競合に関係したブロックの種類（と場所）を確認する – そして、また、これに関与している非常に「hot」なただ1つのブロックがあるか??どうか、多くの異なる "warm"なブロックがあるかどうかを確認する。ブロックが単なるデータ構造であるかのように、ここで「競合を引き起こすブロック」と言わなかったことに注意してください。それは、競合を引き起こしません – このブロックをロックするセッションが引き起こすのです。
- 誰がそのバッファへの《この》ロック（PIN）を保持しているセッションか – そして、すべてを引き起こす1つのブロッキングセッションがあるのか、問題となる多くの異なるセッションがあるのか。
- ブロックしているセッションが何をしているか？ （例えば、他の何かを待ってstuckしている？）
まずは、「伝統的な」アプローチを使用してみましょう。（たとえばSQL監視レポートから）SQL IDとこのSQLが実行中であることを知っていたので、ashtop.sqlスクリプトを使ってASHレコードを問い合わせることができます（出力が広い横幅なことに注意）：
SQL> @ash/ashtop session_state,event sql_id='3rtbs9vqukc71' "timestamp'2013-10-05 01:00:00'" "timestamp'2013-10-05 03: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)
\------ ------- ---------------------------------------------------------------- ------------ ---------- ---------- ----------- ----------- ---------- ------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- --------------------------------------------------------------------------- ---------------------------------------------------------------------------
57% WAITING buffer busy waits 71962 0 0 0 71962 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.09.923 AM 05-OCT-13 02.45.54.106 AM
35% ON CPU 43735 43735 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.34.55.903 AM 05-OCT-13 02.47.28.232 AM
6% WAITING direct path write 6959 0 6959 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.07.923 AM 05-OCT-13 02.47.21.232 AM
1% WAITING external table read 1756 0 1756 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.02.913 AM 05-OCT-13 02.47.15.222 AM
0% WAITING local write wait 350 0 350 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 02.02.40.034 AM 05-OCT-13 02.46.59.202 AM
0% WAITING control file parallel write 231 0 0 0 0 0 0 0 0 0 231 0 0 0 0 05-OCT-13 01.35.22.953 AM 05-OCT-13 02.47.15.222 AM
0% WAITING cell smart file creation 228 0 228 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.09.923 AM 05-OCT-13 02.47.26.232 AM
0% WAITING DFS lock handle 194 0 0 0 0 0 0 0 0 0 0 0 0 0 194 05-OCT-13 01.35.15.933 AM 05-OCT-13 02.47.14.222 AM
0% WAITING cell single block physical read 146 0 146 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.12.933 AM 05-OCT-13 02.47.09.212 AM
0% WAITING control file sequential read 63 0 0 0 0 0 0 0 0 0 63 0 0 0 0 05-OCT-13 01.35.17.953 AM 05-OCT-13 02.46.56.192 AM
0% WAITING change tracking file synchronous read 57 0 0 0 0 0 0 0 0 0 0 0 0 0 57 05-OCT-13 01.35.26.963 AM 05-OCT-13 02.40.32.677 AM
0% WAITING db file single write 48 0 48 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.38.21.317 AM 05-OCT-13 02.41.55.794 AM
0% WAITING gc current grant 2-way 19 0 0 0 0 0 0 19 0 0 0 0 0 0 0 05-OCT-13 01.35.06.923 AM 05-OCT-13 02.45.46.096 AM
0% WAITING kfk: async disk IO 13 0 0 0 0 0 0 0 0 0 13 0 0 0 0 05-OCT-13 01.42.34.791 AM 05-OCT-13 02.38.19.485 AM
0% WAITING resmgr:cpu quantum 9 0 0 0 0 0 0 0 0 0 0 9 0 0 0 05-OCT-13 01.36.09.085 AM 05-OCT-13 01.59.08.635 AM
0% WAITING enq: CR - block range reuse ckpt 7 0 0 0 0 0 0 0 0 0 0 0 0 0 7 05-OCT-13 02.12.42.069 AM 05-OCT-13 02.40.46.687 AM
0% WAITING latch: redo allocation 3 0 0 0 0 0 0 0 0 0 0 0 0 0 3 05-OCT-13 02.10.01.807 AM 05-OCT-13 02.10.01.807 AM
0% WAITING Disk file operations I/O 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.41.13.639 AM 05-OCT-13 01.43.50.951 AM
0% WAITING enq: XL - fault extent map 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 05-OCT-13 01.35.34.983 AM 05-OCT-13 01.35.34.983 AM
0% WAITING external table open 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.02.913 AM 05-OCT-13 01.35.02.913 AM
DB時間の57%は、buffer busy waitsの待機に費やされました。それでは、《我々が扱っている》（データ?ファイル内の）どのブロック#か、どのブロッククラス#を確認するために、P2/P3をチェックしてみましょう。
SQL> @ash/ashtop session_state,event,p2text,p2,p3text,p3 sql_id='3rtbs9vqukc71' "timestamp'2013-10-05 01:00:00'" "timestamp'2013-10-05 03:00:00'"
%This SESSION EVENT P2TEXT P2 P3TEXT P3 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)
\------ ------- ---------------------------------------------------------------- ------------------------------ ---------- ------------------------------ ---------- ------------ ---------- ---------- ----------- ----------- ---------- ------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- --------------------------------------------------------------------------- ---------------------------------------------------------------------------
57% WAITING buffer busy waits block# 2 class# 13 71962 0 0 0 71962 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.09.923 AM 05-OCT-13 02.45.54.106 AM
31% ON CPU file# 0 size 524288 38495 38495 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.05.923 AM 05-OCT-13 02.47.25.232 AM
1% WAITING external table read file# 0 size 524288 1756 0 1756 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.02.913 AM 05-OCT-13 02.47.15.222 AM
1% ON CPU block# 2 class# 13 945 945 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.16.943 AM 05-OCT-13 02.45.10.056 AM
0% ON CPU consumer group id 12573 0 353 353 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.34.56.903 AM 05-OCT-13 01.59.59.739 AM
0% WAITING cell smart file creation 0 0 228 0 228 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.09.923 AM 05-OCT-13 02.47.26.232 AM
0% WAITING DFS lock handle id1 3 id2 2 193 0 0 0 0 0 0 0 0 0 0 0 0 0 193 05-OCT-13 01.35.15.933 AM 05-OCT-13 02.47.14.222 AM
0% ON CPU file# 41 size 41 118 118 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.34.56.903 AM 05-OCT-13 01.35.02.913 AM
0% WAITING cell single block physical read diskhash# 4004695794 bytes 8192 85 0 85 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.12.933 AM 05-OCT-13 02.47.09.212 AM
0% WAITING control file parallel write block# 1 requests 2 81 0 0 0 0 0 0 0 0 0 81 0 0 0 0 05-OCT-13 01.35.22.953 AM 05-OCT-13 02.41.54.794 AM
0% WAITING control file parallel write block# 41 requests 2 74 0 0 0 0 0 0 0 0 0 74 0 0 0 0 05-OCT-13 01.35.31.983 AM 05-OCT-13 02.47.15.222 AM
0% WAITING change tracking file synchronous read blocks 1 0 57 0 0 0 0 0 0 0 0 0 0 0 0 0 57 05-OCT-13 01.35.26.963 AM 05-OCT-13 02.40.32.677 AM
0% WAITING control file parallel write block# 42 requests 2 51 0 0 0 0 0 0 0 0 0 51 0 0 0 0 05-OCT-13 01.35.23.953 AM 05-OCT-13 02.47.10.212 AM
0% WAITING db file single write block# 1 blocks 1 48 0 48 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.38.21.317 AM 05-OCT-13 02.41.55.794 AM
0% ON CPU 0 0 31 31 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.19.953 AM 05-OCT-13 02.44.32.006 AM
0% WAITING control file parallel write block# 39 requests 2 21 0 0 0 0 0 0 0 0 0 21 0 0 0 0 05-OCT-13 01.36.35.125 AM 05-OCT-13 02.39.30.575 AM
0% WAITING control file sequential read block# 1 blocks 1 20 0 0 0 0 0 0 0 0 0 20 0 0 0 0 05-OCT-13 01.35.17.953 AM 05-OCT-13 02.46.56.192 AM
0% ON CPU locn 0 0 19 19 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.35.34.983 AM 05-OCT-13 02.30.34.786 AM
0% ON CPU fileno 0 filetype 2 16 16 0 0 0 0 0 0 0 0 0 0 0 0 0 05-OCT-13 01.36.08.075 AM 05-OCT-13 02.44.26.996 AM
0% WAITING kfk: async disk IO intr 0 timeout 4294967295 13 0 0 0 0 0 0 0 0 0 13 0 0 0 0 05-OCT-13 01.42.34.791 AM 05-OCT-13 02.38.19.485 AM
データファイルのブロック#2でbuffer busy wait？おなじみのもののようだが・・・しかし、（どんなタイプを確認するために）推測したりブロックをダンプする代わりに、《以下のコマンドを使って》ブロッククラス#13が何であるかを確認できます。
SQL> @bclass 13
CLASS UNDO_SEGMENT_ID
\------------------ ---------------
file header block
だから、ブロック#2は、「file header block」と呼ばれるものです。本当のデータ?ファイル?ヘッダー?ブロックであるブロック#1と混同しないでください、（私たちはマニュアルOracle Database概要で知っているように）ブロック#2は、実際に私が見たLMT《ローカル管理》表領域管理ビットマップヘッダブロックである。（P1値からそのファイル#が16であったので、、ALTER SYSTEM DUMP DATAFILE 16 BLOCK 2 コマンドでブロックをダンプした）：
Start dump data blocks tsn: 21 file#:16 minblk 2 maxblk 2
Block dump from cache:
Dump of buffer cache at level 4 for tsn=21 rdba=2
BH (0x1e1f25718) file#: 16 rdba: 0x00000002 (1024/2) class: 13 ba: 0x1e1876000
set: 71 pool: 3 bsz: 8192 bsi: 0 sflg: 1 pwc: 2,22
dbwrid: 2 obj: -1 objn: 1 tsn: 21 afn: 16 hint: f
hash: [0x24f5a3008,0x24f5a3008] lru: [0x16bf3c188,0x163eee488]
ckptq: [NULL] fileq: [NULL] objq: [0x173f10230,0x175ece830] objaq: [0x22ee19ba8,0x16df2f2c0]
st: SCURRENT md: NULL fpin: 'ktfbwh00: ktfbhfmt' tch: 162 le: 0xcefb4af8
flags: foreground_waiting block_written_once redo_since_read
LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [2]
Block dump from disk:
buffer tsn: 21 rdba: 0x00000002 (1024/2)
scn: 0x0001.13988a3a seq: 0x02 flg: 0x04 tail: 0x8a3a1d02
frmt: 0x02 chkval: 0xee04 type: 0x1d=KTFB Bitmapped File Space Header
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F6708C71800 to 0x00007F6708C73800
7F6708C71800 0000A21D 00000002 13988A3A 04020001 [........:.......]
7F6708C71810 0000EE04 00000400 00000008 08CEEE00 [................]
そのように、ブロック番号2は、実際には最初の LMT 空き領域管理 ビットマップブロックである。LMTスペースを管理する必要があるたび（エクステントを割り当てるファイルの領域を検索するか、エクステントを解放する）に、データ?ファイルのブロック＃2をPINする必要があります – そして、同じことをしようとする他の全員《全セッション》は待たなければならない。
では、次の質問をする必要があります – 誰が私たちをブロックしている – 誰がそんなに多く、このブロックをPINしたままにしているのか？そして、ブロッカーは何をやっているのか？ASH待機チェーンスクリプトの出番です – 手動で「blocking_session」列の値をルックアップする代わりに、ブロッカー自体が何をしているのかを調べるために、単にCONNECT BYを使用する。
SQL> @ash/ash_wait_chains event2 sql_id='3rtbs9vqukc71' "timestamp'2013-10-05 01:00:00'" "timestamp'2013-10-05 03:00:00'"
\-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS WAIT_CHAIN
\------ ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
35% 43735 -> ON CPU
15% 18531 -> buffer busy waits [file header block] -> ON CPU
7% 9266 -> buffer busy waits [file header block] -> control file parallel write
7% 8261 -> buffer busy waits [file header block] -> cell smart file creation
6% 6959 -> direct path write
5% 6707 -> buffer busy waits [file header block] -> DFS lock handle
4% 4658 -> buffer busy waits [file header block] -> local write wait
4% 4610 -> buffer busy waits [file header block] -> cell single block physical read
3% 4282 -> buffer busy waits [file header block] -> local write wait -> db file parallel write
2% 2801 -> buffer busy waits [file header block]
2% 2676 -> buffer busy waits [file header block] -> ASM file metadata operation
2% 2092 -> buffer busy waits [file header block] -> change tracking file synchronous read
2% 2050 -> buffer busy waits [file header block] -> control file sequential read
この矢印に従えば、このSQLの応答時間の15％が[LMT空き領域管理ヘッダーブロック上]バッファ?ビジー待機の待機に費やされ、ブロッカー（我々はまだどれか分からない）はCPU上にあった。- 何かしている。ブロッカーが「control file parallel write」または「cell smart file creation」- オフロード されたデータファイルの拡張待機イベント- のどちらかを待っている間、バッファ?ビジー待機で待っていた7% + 7% の待機が存在した。
誰が（ユーザ名とどのプログラム）ブロックしていたのかを見てみましょう：
SQL> @ash/ash_wait_chains username||':'||program2||event2 sql_id='3rtbs9vqukc71' "timestamp'2013-10-05 01:00:00'" "timestamp'2013-10-05 03:00:00'"
\-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS WAIT_CHAIN
\------ ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
35% 43732 -> TANEL:(Pnnn) ON CPU
13% 16908 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) ON CPU
6% 6959 -> TANEL:(Pnnn) direct path write
4% 4838 -> TANEL:(Pnnn) buffer busy waits [file header block] -> SYS:(Wnnn) control file parallel write
4% 4428 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) control file parallel write
3% 4166 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) cell smart file creation
3% 4095 -> TANEL:(Pnnn) buffer busy waits [file header block] -> SYS:(Wnnn) cell smart file creation
3% 3607 -> TANEL:(Pnnn) buffer busy waits [file header block] -> SYS:(Wnnn) DFS lock handle
3% 3147 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) local write wait
2% 3117 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) local write wait -> SYS:(DBWn) db file parallel write
2% 3100 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) DFS lock handle
2% 2801 -> TANEL:(Pnnn) buffer busy waits [file header block]
2% 2764 -> TANEL:(Pnnn) buffer busy waits [file header block] -> TANEL:(Pnnn) cell single block physical read
2% 2676 -> TANEL:(Pnnn) buffer busy waits [file header block] -> SYS:(Wnnn) ASM file metadata operation
1% 1825 -> TANEL:(Pnnn) buffer busy waits [file header block] -> SYS:(Wnnn) cell single block physical read
さて、我々はまた、誰が私たちをブロックしましたか？13％の応答時間の行で、我々は、PXスレーブ（私は一つのラインにそれらすべてを折りたたむために、P000と同様に、バックグラウンドプロセスで「n」に置き換えています）を実行している別のTANELユーザーによってブロックされた。待ち時間が4%である上記の4行目で、TANELのPXスレーブは、SYSが実行しているWnnnプロセスによりブロックされていた – それは、非同期のデータ?ファイルの事前拡張のような領域管理のためのworkerの1つだ。データファイル拡張におけるボトルネックが、この中で果たすべき役割を持っているように見えます！《速く起こることがあります》巨大なデータのロードを予期できるとき、（それが大型ファイル表領域★）自分でデータファイルを事前に拡張することができる-しかし、まず最初にすることは、表領域が均一エクステントのサイズ設定ポリシーを持つLMT表領域であり、かつ、最小エクステントサイズは??、私のデータ?ロードのために十分な大きさであるかどうかを、チェックすることである。つまり、大量のデータをロードする最も大きいファクトテーブルは、複数のメガバイト★（私は32メガバイトと256メガバイトのエクステント?サイズとの間で使用しました）の、均一エクステント?サイズのLMT《ローカル管理》表領域に存在する必要があります。AUTOA??LLOCATEはさほどあなたの役にたたない – AUTOA??LLOCATEの場合、ファイルの各64kBのチャンクごとにLMT領域管理ビットマップビットがあるため – 多数の小さなLMT「チャンク」からなる大きなエクステント、または、単一の大きなLMTチャンクで構成される大きなエクステントを検索して割り当てる際に、多くのオーバーヘッドがあります。
次の記事でブロック＃2におけるbuffer busy waitsのトピックに戻る予定だ。 – この記事は待機チェーン全体で誰が何をしていたかについての詳細《を確認するために》、任意のASH列を使用できることを示すことを目的にしています。
そして、将来のもう1つのトピックは、セッション情報にblockingセッション情報が適切に移入されない待機イベント（例えば、ほとんどのラッチおよびミューテックス。バージョンによって異なります）になるでしょう。そこでは、手動による方法がまだ必要とされるでしょう – mutexについては、待機イベントのPARAMETER2値から （排他的に）ブロックしているSIDを抽出することは可能であるが。多分ash_wait_chains v0.3でかな 
?