待ちイベントに関する検証 その７
＜待ちイベントに関する検証 その７＞
ペンネーム： ダーリン
【db_file_sequential_read/db_file_scatterd_read】
早速おさらい。
先週まで複数回に亘ってメモリ上で発生する待ちイベントである、library
cache や、cache buffer chain などのいわゆる ” ラッチ待ち ” について見
てきました。これらは、Oracle が SQL をスムーズに実行するためや、データ
の整合性を保つために必要な内部的なロックが働くために発生しています。
この ” ラッチ待ち ” は、時折、尋常ではないほど SQL の処理速度を低下さ
せることがあり、さらに特定の処理だけではなくデータベース全体のパフォー
マンスを低下させる場合もあります。
さて、今週は次なる待ちイベントへ向かいましょう。難敵はまだまだいます。
先週までの流れで SQL が解析され必要なデータをバッファ・キャッシュ上で
探し当てるところまでやってきました。データがすべてメモリ上に存在すれば
それに越したことはありませんが、世の中そんなに甘くはありません。
当然、ストレージからデータを読み込む羽目になります。ここにも ” 待ちイ
ベント ” が待ち受けています。
今回の待ちイベントも皆さんご存知ではないでしょうか。結構有名です。
まずは、これらの待ちイベントが発生している様子を見てみましょう。
前回までと同様に V$SYSTEM_EVENT を調べることでもわかります。が、今回は
いきなり、SQL のトレースを見ていきます。そのほうが具体的な発生状況が見
えてくると思いますので。
待ちイベントを含めて SQL トレースを取得しますので、下記のコマンドを実
行します。
alter session set events ‘10046 trace name context forever, level 12’;
その前に、ディスク I/O が発生することが前提なので、一旦、バッファ・キ
ャッシュをクリアしておきましょう。
SQL> alter system flush buffer_cache;
System altered.
改めて、SQL トレースをセットします。
SQL> alter session set events ‘10046 trace name context forever, level 12’;
Session altered.
ここで SQL を実行してトレースを取得します。
トレースファイルは、初期化パラメータの user_dump_dest に指定されたディ
レクトリに出力されます。
SQL> select * from emp_test;
………………….
100000 rows selected.
トレースを取ったら設定は元に戻しておきましょう。
SQL> alter session set events ‘10046 trace name context off’;
Session altered.
さて、どんなトレースが取れているでしょうか。
以下に、対象のSQLの部分を抜き出してみました。
------- ここから ----------------------------------------------------- .......... <省略> ................. =================== PARSING IN CURSOR #5 len=22 dep=0 uid=76 oct=3 lid=76 tim=1143865915961 select * from emp_test END OF STMT PARSE #5:c=0,e=142,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143865915961 BINDS #5: EXEC #5:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=114386591596191 WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #b WAIT #5: nam='db file sequential read' ela= 24 file#=15 block#=44179 bl WAIT #5: nam='db file scattered read' ela= 81 file#=15 block#=44180 blo FETCH #5:c=0,e=412,p=6,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=1143865915962 WAIT #5: nam='SQL*Net message from client' ela= 416 driver id=165081523 WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #b FETCH #5:c=0,e=91,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,tim=1143865915963 WAIT #5: nam='SQL*Net message from client' ela= 2609 driver id=16508152 WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #b FETCH #5:c=0,e=69,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143865915965 WAIT #5: nam='SQL*Net message from client' ela= 2326 driver id=16508152 WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #b FETCH #5:c=0,e=74,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,tim=1143865915968 ................... ------- ここまで -----------------------------------------------------
最初のほうに今回狙った待ちイベントが出ていますね。
“db file sequential read” と “db file scattered read” の部分を細かく見て
みます。
-----------------------------------------------------------------------
WAIT #5: nam='db file sequential read' ela= 24
file#=15 block#=44179 blocks=1 obj#=74029 tim=1143865915962092
WAIT #5: nam='db file scattered read' ela= 81
file#=15 block#=44180 blocks=5 obj#=74029 tim=1143865915962372
FETCH #5:c=0,e=412,p=6,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=1143865915962427
-----------------------------------------------------------------------
最初に 1 ブロック読み込んだ際には、”db file sequential read” の待ちが
発生し、続いて5 ブロック読み込んだ際に、”db file scattered read” の待
ちが発生しています。どちらが複数ブロック読み込んだときの待ちイベントか
はこれで確認できましたね。
気をつけたいのは、V$SYSTEM_EVENTなどのでこれらの待ちイベントをチェック
しているときです。
実際の環境で、全件検索が多くディスク I/O の多発している場合は全件検索
によるディスク I/O のボトルネックにより、インデックス検索などのシング
ルブロックへのアクセスが遅くなることが良くあります。この場合
“db file sequential read” が大きくなることがあるので（名前の問題もあり
ますが）こちらを全件検索の待ちイベントだと勘違いしてしまうことがありま
す。
もうひとつ注意点を。
今回対象にしたSQLの実行計画を確認すると、、
SQL> set aoutotrace trace SQL> select * from emp_test; 100000 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 3124080142 ------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 99596 | 3598K| 142 (3)| 00:00:02 | | 1 | TABLE ACCESS FULL| EMP_TEST | 99596 | 3598K| 142 (3)| 00:00:02 | ------------------------------------------------------------------------------
ということで、実は全件検索でした。
でも、待ちイベントには “db file sequential read” も出ていましたね。
つまり、
「”db file scattered read” = 全件検索による待ちイベント」
ではなく、反対に
「”db file sequential read” = インデックス検索による待ちイベント」
でもない。
ということです。
正確には
「”db file scattered read” = 複数ブロック読み込みによる待ちイベント」
「”db file sequential read” = 単独ブロック読み込みによる待ちイベント」
ということです。
たぶん同じ解説はどこかしらで見かけているはずなのですが、しばらくチュー
ニングの現場から離れていると皆さん忘れてしまうことが多いようです。
来週もこのイベントをもう少し見ていきましょう。
Welcom to Our Insight World 2007
茅ヶ崎にて