演習2で実行したSELECT文をさらに5回実行し、再度、動的パフォーマンスビュー V$SQLで対象のSELECT文の情報を確認してみましょう。
/* TRYユーザーで演習2のSELECT文をさらに5回実行後 */ SQL> select SQL_ID, EXECUTIONS, PARSE_CALLS, CPU_TIME, ELAPSED_TIME, ELAPSED_TIME - CPU_TIME, USER_IO_WAIT_TIME, DISK_READS,PHYSICAL_READ_BYTES from V$SQL where SQL_ID = '2vrywhbx1jxtb'; SQL_ID EXECUTIONS PARSE_CALLS CPU_TIME ELAPSED_TIME ELAPSED_TIME-CPU_TIME USER_IO_WAIT_TIME DISK_READS PHYSICAL_READ_BYTES ------------- ---------- ----------- ---------- ------------ --------------------- ----------------- ---------- ------------------- 2vrywhbx1jxtb 6 6 219966 1313478 1093512 1164674 390 3194880
対象のSQL文の総実行回数を示す「EXECUTIONS」列の値と、合計パース回数を示す「PARSE_CALLS」列がそれぞれ1+5で「6」へ増加していることから、本当に5回追加実行したことを証明できます。そして、「CPU_TIME」列の値が前回(EXECUTIONS=1の場合)の169974マイクロ秒から、今回(EXECUTIONS=6)は219966マイクロ秒へ増加してはいます。しかし6倍までには増えていません。ここに気付かれた方は鋭い。まさにこの初回と2回目以降のCPU時間の増加量の差が、ハードパースとソフトパースの違いによるものです。
CPU時間と経過時間の差が生じる要因を3つ挙げておきます。1つ目はデータが記録されているデバイス(HDDやフラッシュデバイスなど)からレコードが格納されている「データブロックの読み込み待ち」のために、つまり、CPUで処理すべきデータの到着を待っているためにCPUが使えない時間があること。2つ目は「ネットワーク転送」でデータの到着を待っているためにCPUが使えない時間があること。3つ目は、同時に複数のSQL文の実行を要求される「高負荷(CPU使用率が100%)の状態」であるために、CPUを使いたくても使えない時間があることです。
これらの切り分けとしては、OS層でのCPU使用率やネットワーク転送量を分析する手段もありますが、上記の例ではV$SQLの「USER_IO_WAIT_TIME」列(I/O待機時間:単位はマイクロ秒)と、「ELAPSED_TIME」から「CPU_TIME」を引いた値を見比べてください。ほぼ同じ値を示しています。ですから、1つ目の「データブロックの読み込み待ちが原因」とおおよその推測が可能です。
この他に、「DISK_READS」列(読み込みブロック数)や「PHYSICAL_READ_BYTES」列(HDDから読み込んだバイト数)からも実際に記憶デバイスからの読み込みが発生していたことが確認できます。また、EXECUTIONS=「1」の場合とEXECUTIONS=「6」の場合で「ELAPSED_TIME」から「CPU_TIME」を引いた値が大きく変化していない理由として、EXECUTIONS=「1」の際にデータブロックをバッファキャッシュにキャッシュし、2回目以降は記憶デバイスからデータブロックを読み込んでいない、つまり「データブロックの読み込み待ちが発生していない」と読み解くこともできます。
SQLの実行計画を取得できたとしても、それを読み取るスキルも身に付けなければ意味がありません。今回は、「さらに高度なSQLの実行計画の取得方法」を実践する前に、Oracle Databaseの仕組みやパフォーマンスを計る重要な観点であるCPU時間やディスク待機時間の考え方を解説しました。
次回は動的パフォーマンスビュー V$SQLから取得した「SQL_ID」や「CHILD_NUMBER」を用いて、リアルタイムSQL監視レポートをコマンドラインで取得する方法を紹介します。それではまた次回お会いしましょう!
Copyright © ITmedia, Inc. All Rights Reserved.