続・バッファキャッシュ関連の待機イベントとパフォーマンス統計情報を読み解く：しばちょう先生の試して納得！ DBAへの道（改）（6）（1/4 ページ）

データベース技術や知識は、座学だけでなく「実際に手を動かして、実際に試して」理解を深めよう──。日本オラクルのデータベーススペシャリストが「新人をDBAに育てる際に使用する課題」をベースに、DBAがすぐ実践できる即効テクニックを紹介。今回は「バッファキャッシュ関連の待機イベントとパフォーマンス統計情報の読み解き方」について、前回に引き続き解説します。

[柴田長，日本オラクル株式会社]

※本連載は、日本オラクルの技術解説ブログ「Oracle Technology Network：しばちょう先生の試して納得！DBAへの道」より、提供者の許可の下、最新情報の追記とともに一部改訂して転載するものです。

連載バックナンバー

　皆さんこんにちは。日本オラクルの“しばちょう”こと、柴田長（しばたつかさ）です。

　「データベースのパフォーマンス問題が発生しました！」そのような際に活躍するのがAWRレポートやStatspackレポートです。しかし、そこに絶妙なタッチで描かれている待機イベントやパフォーマンス統計情報の意味が分からなければ、問題を解決することはできません。

　今回は前回の記事の続きで、バッファキャッシュ関連の待機イベントやパフォーマンス統計情報の読み解き方を体験してみましょう。使用するスキーマは前回作成したものを利用します。

1.SQL単体実行での待機イベントを確認する

　「SYS」ユーザーでバッファキャッシュ上のデータブロックをフラッシュした後、「TRY」ユーザーにてevents 10046のSQLトレースを設定し、さらにその後、前回の演習3で実行したクエリ（TAB39_SMALL表に対してTABLE ACCESS FULLを行う）を再実行します。

$ sqlplus / as sysdba
SQL>
/* テストの都合上、バッファキャッシュ上のデータをフラッシュ */
alter system flush buffer_cache ;
connect TRY/TRY
/* このセッションでのみ、SQLトレースのイベントの有効化 */
alter session set events '10046 trace name context forever, level 12' ;
/* クエリ実行*/
select /*+FULL(t) */ sum(ora_hash(COL2, 10)) from TAB39_SMALL t ;
/* SQLトレースのイベントの無効化 */
alter session set events '10046 trace name context off' ;
/* トレースファイル名の特定 */
SQL> !ps
  PID TTY          TIME CMD
 2221 pts/0    00:00:00 bash
 3508 pts/0    00:00:00 sqlplus
 3913 pts/0    00:00:00 ps
SQL> !ps -ef | grep 3508 | grep "DESCRIPTION=" | grep -v grep
oracle    3904  3508  0 15:07 ?        00:00:00 oracleorcl (DESCRIPTION=(LOCAL...
/* トレースファイルの確認 */
$ vi /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3904.trc
=====================
PARSING IN CURSOR (省略) ... sqlid='fgsp4fbsnj738'
select /*+FULL(t) */ sum(ora_hash(COL2, 10)) from TAB39_SMALL t
END OF STMT
PARSE (省略):c=1000,e=612,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1, ...
EXEC (省略):c=0,e=327,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1, ...
WAIT (省略): nam='db file sequential read' ela= 804 file#=5 block#=1154 blocks=1 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 560 file#=5 block#=1155 blocks=5 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 910 file#=5 block#=1160 blocks=8 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 1035 file#=5 block#=1169 blocks=7 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 1059 file#=5 block#=28449 blocks=7 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 1614 file#=5 block#=28456 blocks=8 obj#=15714 ...
WAIT (省略): nam='db file scattered read' ela= 891 file#=5 block#=28465 blocks=7 obj#=15714 ...
(以降、省略)

　本来は、SQL監視レポートで待機イベントを取得できれば良かったのですが、実行時間が非常に短くてサンプリングされなかったため、より正確に待機イベントの発生状況を確認することが可能な、events 10046のSQLトレースを使用してみました。掲載しておいてなんですが、私も基本的には、いざという時にしか使用しませんし、SQL監視レポートで代用できますからおすすめしていません。興味のある方は、My Oracle Supportで使い方、読み方を学習して、自己責任で使用してくださいね。

　Event 10046のSQLトレースが出力されるトレースファイルは、アラートログファイルと同一のディレクトリ内にありますが、このディレクトリには拡張子「.trc」のファイルが数多く存在しているため、特定することが少し難しいです。生成された時刻で特定しても良いですし、ファイル名に含まれている数字から特定することも可能です。この数字はSQLトレースを出力したサーバプロセスのプロセスIDを意味していますので、SQLトレースを取得したsqlplusからフォークされたサーバープロセスの、プロセスID（上述の回答例では3904）を調べることで特定しています。ぜひ参考にしてみてください。

　取得されたトレースを確認してみると、1回の「db file sequential read」待機イベントが発生した後、「db file scattered read」待機イベントが連続して発生していることが確認できます。とても面白いですね。各行の待機イベントには「blocks」という記載がありますが、これが「1」の場合にはシングルブロック読み込み、「2以上」の場合にはマルチブロック読み込みを意味しますから、「db file sequential read待機イベントはシングルブロック読み込み時に発生し、db file scattered read待機イベントはマルチブロック読み込み時に発生する」と理解できますね。

　さらに、次の演習でも解説させていただきますが、どちらの待機イベントも「バッファキャッシュ上へのブロック読込み時」に発生することを、合わせて覚えておきましょう。勘の良い方は気付かれていると思うので書いておきますが、「ディスクからブロックを読み込むが、バッファキャッシュ上への読み込みでなければ別の待機イベントになる」ことも意味していますね。