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

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

3.索引を使用した表アクセスを行うクエリを実行した際の、パフォーマンス統計情報と待機イベントの確認（失敗例）

　同様に、TAB39_SMALL表の主キーの値を条件指定したクエリを連続実行した際のパフォーマンス統計情報と、発生した待機イベントについて確認します。

$ sqlplus TRY/TRY
SQL>
/* クエリの実行計画を確認 */
variable B1 number ;
execute :B1 := 1 ;
set autotrace on explain
select COL2 from TAB39_SMALL t where COL1 = :B1 ;
Execution Plan
----------------------------------------------------------
Plan hash value: 1853248505
-------------------------------------------------------------------------------
| Id  | Operation                   | Name                 | Rows  | Bytes |...
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                      |     1 |  1005 |...
|   1 |  TABLE ACCESS BY INDEX ROWID| TAB39_SMALL          |     1 |  1005 |...
|*  2 |   INDEX UNIQUE SCAN         | IDX_TAB39_SMALL_COL1 |     1 |       |...
-------------------------------------------------------------------------------
$ ### Linuxコマンドで連続実行用のSQLファイル(sql_loop.sql)を作成
echo "alter session set events '10046 trace name context forever, level 12' ;"
> sql_loop.sql
for i in `seq 0 7 6272`; do
  echo "variable B1 number ;"
  echo "execute :B1 := $i ;"
  echo "select COL2 from TAB39_SMALL t where COL1 = :B1 ;"
done >> sql_loop.sql
echo "alter session set events '10046 trace name context off' ;" >> sql_loop.sql
echo "
set lines 150 pages 5000
col NAME for a48
select S.NAME, M.VALUE
  from V\$MYSTAT M, V\$STATNAME S
 where M.STATISTIC# = S.STATISTIC#
   and S.NAME like 'physical read%'
 order by 1 ;" >> sql_loop.sql

$ sqlplus / as sysdba
SQL>
/* テストの都合上、バッファキャッシュ上のデータをフラッシュ */
alter system flush buffer_cache ;
/* クエリの連続実行 */
connect TRY/TRY
@sql_loop.sql
NAME                                                  VALUE
------------------------------------------------ ----------
physical read IO requests                               126
physical read bytes                                 7741440
physical read flash cache hits                            0
physical read partial requests                            0
physical read requests optimized                          0
physical read total IO requests                         126
physical read total bytes                           7741440
physical read total bytes optimized                       0
physical read total multi block requests                  0
physical reads                                          945
physical reads cache                                    945
physical reads direct                                     0
physical reads direct (lob)                               0
physical reads direct temporary tablespace                0
physical reads for flashback new                          0
physical reads prefetch warmup                          819
physical reads retry corrupt                              0
/* バッファキャッシュ上にキャッシュされたオブジェクトとサイズ */
connect / as sysdba
col OWNER for a8
col OBJECT_NAME for a24
select OWNER, OBJECT_NAME, count(*) "BUFFERS", count(*)*8/1024 "MB"
  from V$BH, DBA_OBJECTS
 where OBJD = DATA_OBJECT_ID and OWNER = 'TRY' and V$BH.STATUS != 'free'
 group by OWNER, rollup(OBJECT_NAME)
 order by 4 ;
OWNER    OBJECT_NAME                 BUFFERS         MB
-------- ------------------------ ---------- ----------
TRY      IDX_TAB39_SMALL_COL1             14    .109375
TRY      TAB39_SMALL                     896          7
TRY                                      910   7.109375

　前半部分は、索引を使用して表へアクセスするSQLを連続実行するためのSQLファイルを作成しているだけですので、それほど難しい内容ではないと思います。バインド変数の使用方法等は参考になると思います。

　実行計画として、索引を使用した表アクセス（TABLE ACCESS BY INDEX ROWID）が行われるクエリを連続実行していくわけですから、これまで体験してきた「1回のクエリでTable Full Scanでマルチブロック読み込みを行う処理」とは異なる点は、ご理解いただけると思います。よって、マルチブロック読み込みを示すパフォーマンス統計情報「physical read total multi block requests」がカウントアップしていません。少しずつパフォーマンス統計情報が読めるようになってきましたね。しかし、油断してはなりませんよ。そんな簡単な演習問題を私が出すはずがありません。ということで、またまた登場のevents 10046のSQLトレースの結果を見てみることにしましょう。

$ cat orcl_ora_5313.trc | grep "db file"
(省略)
WAIT (省略): nam='db file scattered read' ela= 1234 file#=5 block#=1160 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 821 file#=5 block#=1168 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 1128 file#=5 block#=28440 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 1599 file#=5 block#=28448 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 1089 file#=5 block#=28456 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 1401 file#=5 block#=28464 blocks=8 ...
WAIT (省略): nam='db file scattered read' ela= 965 file#=5 block#=28472 blocks=8 ...
(省略)
$ cat orcl_ora_5313.trc | grep "db file sequential read" | wc -l
1
$ cat orcl_ora_5313.trc | grep "db file scattered read" | wc -l
117

　繰り返しになりますが、この演習のクエリは、「索引を使用した表アクセス（TABLE ACCESS BY INDEX ROWID）」です。Bツリー索引の各ブロックを1つずつアクセスして該当のリーフブロックにたどりつき、そこで特定されたROWIDを使用して表内の特定の1つのブロックを読み込む。というように順番（sequential）にシングルブロックを読み込む処理ですから、db file sequential read待機イベントが発生するはずなのですが……。いかがでしょうか？　どうもおかしいですね。ディスクからバッファキャッシュ上へのマルチブロック読み込みを示すdb file scattered read待機イベントばかりが発生してしまっています。一般的には、索引を使用した表アクセス（TABLE ACCESS BY INDEX ROWID）では、ディスクからバッファキャッシュ上へシングルブロック読み込みを示すdb file sequential read待機イベントが発生します。しかし、今回はdb file scattered read待機イベントが発生していました。これは例外であり、「Pre-Warming機能」が動作した可能性を疑ってください。

　Pre-Warming機能は、バッファキャッシュに余裕がある（空き領域が存在する）場合に限定して、1つのブロックをバッファキャッシュへ読み込む処理が発生した時に、その周辺のブロックも一緒にマルチブロック読み込みしてしまう機能です。何かメリットがあるのかというと、「バッファキャッシュの暖気を早くする」と表現すると分かりやすいかもしれませんね。「1つのブロックを読んだのだから、その周辺もそのうち読まれるかもしれない。バッファキャッシュの空きに余裕があるのだから、一緒にバッファキャッシュに読み込んでおいてしまえ」と賢く動作してくれています。

　例えば、朝方にインスタンスの再起動を行いバッファキャッシュが空の状態からオンライン業務がスタートすることがあります。索引アクセスのクエリしか実行していないのに、db file scattered read待機イベントが発生したため、「索引アクセスが最適なクエリの実行計画が、非効率な全表検索（TABLE ACCESS FULL）に変化してしまったのか？」と現場のDBAが慌てている姿を見たことがあります。ここでは、Pre-Warming機能が動作している可能性があることを覚えておいてくださいね。実際に上述の実行後のパフォーマンス統計情報では、Pre-Warming機能が動作したことを示す「physical reads prefetch warmup」がカウントアップしていることが確認できます。

　上記で、「バッファキャッシュの空きに余裕がなければ、Pre-Warming機能が発生しない」ことが理解できたと思うので、その状態を作り直して、改めてdb file sequential read待機イベントが発生するケースを見ていきましょう。