この投稿はJPOUG in 15 minutes #8で発表した内容に加筆・整理したものです。
実行統計とは？
実行統計とは、DBMS_XPLANパッケージのDISPLAY_CURSOR関数における機能拡張で、SQL実行時に実行計画の各ステップ毎に出力行数や実行時間などの統計情報を取得し、実行後（正常終了および強制終了）に実行計画と共に統計情報を併記するものである。
ちなみに、本機能はOracle10g R2以降で使用可能となっている。
実行統計については以下の記事がよくまとまっている。
Oracle DatabaseでSQLの性能計測2(DBMS_XPLAN＆DBMS_SQLTUNE編)【Oracle Database or GoldenGate Advent Calendar 2018 Day 8】
Oracle® Database SQLチューニング・ガイド 12c リリース1 (12.1) には以下の記述がある。
V$SQL_PLANビューを使用した計画の評価のガイドライン
ポイントをまとめると以下の2点となる。
- 出力行数や経過時間など、計画に含まれる操作ごとに実際の実行統計を出力する。
- 出力行数を除き、すべての統計は累積される。例えば結合操作の統計には、2つの入力の統計も含まれる。
実行統計が使えない時は、SQL文の性能は全体の経過時間と各ステップごとのコスト値で評価するしかなかった。
コスト値はリンクにあるように、性能を評価する絶対的な指標ではなく、実行時間と相関するものではない。
別の言い方をすると、I/OコストとCPUコストで見積もられる「コスト」を最小にするような実行計画を立案するのがコスト・ベース・オプティマイザ（CBO）であるが、コストの大小が必ずしも実行時間の長短でないことがSQLチューニングを難しくしているというのが、実行統計が実装される以前の課題であった。
一方、実行計画の各ステップごとに経過（累積）時間を表示させることができる実行統計により、SQLの中でボトルネックがどこに存在するかを的確に把握することができるので、以前のような「試行錯誤」的チューニングと比べ、より効率的なチューニングが可能となった。
SQL単性能試験の実際
それでは、SQL単性能試験をイメージして実践的なSQLチューニングの実際を考えてみよう。
SQL単性能試験とは、SQL*PlusからSQL文を単体で実行する試験であり、設定した性能目標（レスポンス、スループット）を達成するまでチューニングを行うものである。
アプリケーションが発行しうるすべてのSQL文を予め単体で実行し、性能上の問題点を完全に解決した上で、次の段階（総合試験等）に進むべきである。
カットオーバー直前で致命的な性能問題が発生することのないよう、十分なSQL単体試験を実施することは円滑なプロジェクト遂行にとって重要である。
考慮すべき点
意味のあるSQL単体試験を実施するために考慮すべき点を以下に挙げる。
1. 本番相当データ
SQL単性能試験を行う上で最も重要なのは、量および質で本番と同等のデータを使用することである。量とは将来の増加量を見越した十分なサイズ、質とは現実的な内容（値の分布等）のデータを準備することである。
セキュリティ面から本番データをそのまま試験で使うことは許されないことが多いが、本番データとあまりにもかけ離れたデータを使っては性能試験の妥当性を担保できない。
2. キャッシュ・クリア
SQL単性能試験を行う際、キャッシュをクリア（フラッシュ）した状態で実行時間を計測する。
キャッシュとはDBバッファおよび共有プールである。
キャッシュをクリアした状態でそのSQLの本当の実力を把握することができる。
データがDBバッファ上にあるとボトルネックの検出が困難になる。またパーティション数が非常に多い環境ではParseに要する時間が想定以上に長くなることが多く、共有プールをフラッシュすることでその状況を確認することができる。
3. 占有サーバ
性能測定をするサーバでは極力他の負荷がかかっていない状態であることが望ましく、無風状態で測定できるようサーバを占有できる環境が理想である。
著者が経験したあるプロジェクトでは、開発と性能測定を同じサーバで行わざるを得なかったため、測定結果が負荷により毎回変わってしまい客観的な判断ができない場合があった。
STATISTICS_LEVELパラメータを「ALL」に設定
実行統計を取得するために３つの方法がある
- STATISTICS_LEVELパラメータをALLに設定する
- SQL文にGATHER_PLAN_STATISTICSヒントを指定し実行する
- SQLトレースを有効にしてSQL文を実行する
実際にはSQL*Plusでログインしたセッション単位で
alter session set STATISTICS_LEVEL=all;
とするのがよいだろう。
「alter system 〜」によりインスタンス・レベルで設定することも可能だが、実行される全てのSQLの実行統計が取得されSYSAUX表領域が枯渇する可能性があるのでお勧めしない。
キャッシュ・クリア
キャッシュ・クリア（フラッシュ）は以下のスクリプトをSQL実行前に実行することで行う。
pro *** FLUSH SHARED POOL *** alter system flush shared_pool; pro *** FLUSH BUFFER CACHE *** alter system flush buffer_cache;
SQL> @flusys *** FLUSH SHARED POOL *** システムが変更されました。 *** FLUSH BUFFER CACHE *** システムが変更されました。
SQL文の実行と経過時間の確認
それでは、実際にSQLを実行して結果を確認してみよう。
以下のSQLは、実際の業務で実行されたSQLをベースにテーブル名等を書き換えたサンプルSQLである。
コメントにあるように、オンラインSQLとして実行されているが、3分27秒もかかっておりチューニングが必要である。
SELECT /*+ ONLINE_SQL04S
INDEX(T004 I_TABLE004_8) INDEX(T001 I_TABLE001_2)
USE_NL(T002)
LEADING(T001 T004 T002) */
COUNT(*) AS COUNTNUM
FROM
TABLE_004 T004
INNER JOIN
TABLE_001 T001
ON (T004.COL3091 = T001.COL3091
AND T004.COLA269 = T001.COLA269)
LEFT OUTER JOIN
TABLE_002 T002
ON (T002.COLA215 = T001.COLA215
AND T002.COL3091 = T004.COL3091)
WHERE
..... 以下省略 ..........
COUNTNUM
----------
1
経過: 00:03:27.35
SQL_IDの確認
SQLを実行した後、以下のスクリプトでSQL_IDを確認する。
コメントに記述した文字列を引数として実行する。
SET AUTOT OFF
SET COLSEP ' ' VERIFY OFF LINESIZE 140
COLUMN SQL_TEXT FOR A80
COLUMN SQL_ID FOR A13
COLUMN EXECUTIONS FOR '9999999'
COLUMN ELAPSED_TIME FOR '999999999999'
COLUMN LA_DATE FOR A10
COLUMN LA_TIME FOR A8
SELECT /* THISSQL */
SUBSTR(SQL_TEXT, 1, 60) SQL_TEXT
, SQL_ID
, EXECUTIONS
, ELAPSED_TIME
, TO_CHAR(LAST_ACTIVE_TIME, 'YYYY/MM/DD') LA_DATE
, TO_CHAR(LAST_ACTIVE_TIME, 'HH24:MI:SS') LA_TIME
FROM
V$SQL
WHERE
SQL_TEXT LIKE '%&1.%' AND NOT SQL_TEXT LIKE '%THISSQL%'
ORDER BY
LAST_ACTIVE_TIME ASC
;
SQL> @vsql ONLINE_SQL04S
実行統計を併記した実行計画の表示
上で確認したSQL_IDを使用して、実行統計を併記した実行計画を表示させる。
９行目のDBMS_XPLAN.DISPLAY_CURSORと引数の設定がポイントである。
また、１１行目は実行順に実行計画を表示させるスクリプトを呼び出している。（次回解説）
define SQLID=&1
set autot off
set trim on
set pages 10000
set lines 1000
set long 1000000
set longchunksize 1000000
set heading off
select * from table(DBMS_XPLAN.DISPLAY_CURSOR('&SQLID',null,'ALLSTATS LAST'));
set heading on
@aplans &SQLID --実行順実行計画の表示
set lines 80
表示結果（横スクロールあり）
SQL> @aplan bvrwck53tfgkt
SQL_ID bvrwck53tfgkt, child number 0
-------------------------------------
SELECT /*+ ONLINE_SQL04S INDEX(T004 I_TABLE004_8) INDEX(T001
I_TABLE001_2) USE_NL(T002) LEADING(T001 T004 T002) */ COUNT(*) AS
COUNTNUM FROM TABLE_004 T004 INNER JOIN TABLE_001
T001 ON ( T004.COL3091 = T001.COL3091
AND T004.COLA269 = T001.COLA269 )
LEFT OUTER JOIN TABLE_002 T002 ON (
T002.COLA215 = T001.COLA215 AND
T002.COL3091 = T004.COL3091 ) WHERE
T001.COLAH15 = '0' AND T004.COLAH15 = '0'
AND T001.COLA215 =:B1 AND
( T001.COLA293 = '2' OR (
T001.COLA293 = '1' AND T004.COL0157 <> 'B'
) ) AND (
T001.COLA367
Plan hash value: 239732999
------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads |
------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:03:27.34 | 121K| 116K|
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:03:27.34 | 121K| 116K|
|* 2 | COUNT STOPKEY | | 1 | | 1 |00:03:27.34 | 121K| 116K|
|* 3 | FILTER | | 1 | | 1 |00:03:27.34 | 121K| 116K|
|* 4 | FILTER | | 1 | | 1 |00:03:27.34 | 121K| 116K|
| 5 | NESTED LOOPS OUTER | | 1 | 1 | 1 |00:03:27.34 | 121K| 116K|
| 6 | NESTED LOOPS | | 1 | 1 | 1 |00:03:27.33 | 121K| 116K|
|* 7 | TABLE ACCESS BY INDEX ROWID BATCHED | TABLE_001 | 1 | 38046 | 3060 |00:00:03.12 | 3706 | 1977 |
|* 8 | INDEX SKIP SCAN | I_TABLE001_2 | 1 | 38050 | 3060 |00:00:02.96 | 3619 | 1917 |
| 9 | PARTITION RANGE ITERATOR | | 3060 | 1 | 1 |00:03:24.20 | 117K| 114K|
|* 10 | TABLE ACCESS BY LOCAL INDEX ROWID BATCHED| TABLE_004 | 3060 | 1 | 1 |00:03:24.19 | 117K| 114K|
|* 11 | INDEX RANGE SCAN | I_TABLE004_8 | 3060 | 1 | 1 |00:03:24.17 | 117K| 114K|
|* 12 | INDEX RANGE SCAN | I_TABLE002PK | 1 | 1 | 0 |00:00:00.01 | 1 | 1 |
------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter(ROWNUM<=TO_NUMBER(:B6)) 3 - filter(:B5>=:B4)
4 - filter(("T001"."COLA367"='0' OR ("T001"."COLA367"='1' AND INTERNAL_FUNCTION("T004"."COL0310") AND
"T002"."COLA362"="T004"."COLA363" AND "T002"."COLA364"<=LPAD(NVL("T004"."COLA366",'000'),3,'0') AND "T002"."COLA365">=LPAD(NVL("T004"."COLA366",'000'),3,'0'))))
7 - filter(("T001"."COLA389"='0' OR "T001"."COLA389"='1' OR "T001"."COLA389"='2'))
8 - access("T001"."COLA215"=:B1 AND "T001"."COLAH15"='0')
filter(("T001"."COLA215"=:B1 AND INTERNAL_FUNCTION("T001"."COLA332") AND "T001"."COLAH15"='0'))
10 - filter((DECODE("T001"."COLA389",'2',NVL("T004"."COLA526",'19000101'),'19000101')<NVL("T001"."COL3277",'21001231')
AND (INTERNAL_FUNCTION("T001"."COLA389") OR ("T001"."COLA389"='2' AND INTERNAL_FUNCTION("T004"."COLA415"))) AND
("T001"."COLA293"='2' OR ("T001"."COLA293"='1' AND "T004"."COL0157"<>'B'))))
11 - access("T004"."COLA269"="T001"."COLA269" AND "T004"."COL3091"="T001"."COL3091" AND "T004"."COL0017">=:B4 AND
"T004"."COLA318"=:B3 AND "T004"."COLAH15"='0' AND "T004"."COL0017"<=:B5) filter(("T004"."COLA318"=:B3 AND DECODE("T001"."COLA389",'2',"T004"."COL0017",'21001231')>=:B2 AND
"T004"."COLAH15"='0' AND INTERNAL_FUNCTION("T004"."COLA415")))
12 - access("T002"."COLA215"=:B1 AND "T002"."COL3091"="T004"."COL3091")
57行が選択されました。
経過: 00:00:00.39
項目説明
Starts : そのステップが実行された回数
E-Rows : CBOが見積もった（１回あたりの）処理行数
A-Rows : そのステップでの処理行数
A-Time : （累積）実行時間
Buffers : バッファ・アクセス数
Reads : ディスクから読み込まれたブロック数
ステップの実行順
実行計画ツリーの見方は「右から左、上から下」が基本である。
上の実行計画では、インデントの一番深いId=11が一番最初に実行されるように思ってしまうが、実際はId=6「NESTED LOOPS」の最初の入力側（駆動表又は外部表）となるId=8「INDEX SKIP SCAN」が一番最初に実行される。
実行順をまとめると
8 → 7 → 11 → 10 → 9 → 6 → 12 → 5 → 4 → 3 → 2 → 1 → 0
となり、Id=0のA-Time 3:27.34 がこのSQLの実行時間となる。（SQL*Plusのtiming表示の経過時間と若干異なることに注意）
実行統計を併記するようにしても実行順を間違えるとボトルネックの判断を間違えてしまう可能性がある。
ということで、次回は実行計画を実行順に表示させる方法を紹介する。
今回はここまで