月別アーカイブ: 2019年8月

実行統計による実践的SQLチューニング(その2)

実行計画を実行順に表示させる

前回の投稿では、DBMS_XPLANパッケージのDISPLAY_CURSOR関数により実行統計を併記した実行計画の表示要領を紹介した。

しかし、実行計画ツリーからどのステップが起点となりどの順番で実行されるかを読み取るのはある程度の経験が必要であり、前回紹介した程度の行数であればともかく、数百ステップにもなる場合はベテランでも投げ出したくなる。

筆者は以前から実行計画ツリーを実行順に表示させることに関して試行錯誤を繰り返してきたが、この度方法を確立するに至ったので紹介したいと思う。

実行順表示スクリプト

DBMS_XPLAN.DISPLAY_COURSORの入力ソースはV$SQL_PLAN_STATISTICS_ALLビューであるので、このビューを使って情報を取得する。

前回投稿の中で aplan.sql スクリプトから呼ばれていた aplans.sql の内容が以下となる。

set lines 1000
col ID for 9999
col Operation for a60
col Name for a20
col Pstart for a13
col Pstop for a13
col A-Time for 9,990.00
col A-Rows for 999,999,999,990
col E-Rows for 999,999,999,990
col Starts for 999,999,999,990
-- 実行順実行統計出力
select
 ID
,"Operation"
,"Name"
,"Starts"
,"E-Rows"
,"A-Rows"
,"A-Time"
,"Buffers"
,"Reads"
,"Writes"
,"Srch Cols"
,"Pstart"
,"Pstop"
,"PartID"
from
(
  select
   rownum NO
  ,ID
  ,lpad(' ',DEPTH) || OPERATION ||' '|| OPTIONS "Operation"
  ,OBJECT_NAME "Name"
  ,LAST_STARTS "Starts"
  ,nvl(CARDINALITY,1) * LAST_STARTS "E-Rows" -- 1回の操作で処理される見積行数 * 見積処理回数 = 見積処理行数
  ,LAST_OUTPUT_ROWS "A-Rows"                 -- 実際の処理行数
  ,LAST_ELAPSED_TIME/1000000 "A-Time"
  ,LAST_CR_BUFFER_GETS "Buffers"
  ,LAST_DISK_READS "Reads"
  ,LAST_DISK_WRITES "Writes"
  ,SEARCH_COLUMNS "Srch Cols"
  --,COST
  ,PARTITION_START "Pstart"
  ,PARTITION_STOP "Pstop"
  ,PARTITION_ID "PartID"
  from
  (
    select a.* from 
     V$SQL_PLAN_STATISTICS_ALL a
    where a.SQL_ID    = '&1'
    and   a.TIMESTAMP = (select max(b.TIMESTAMP) from V$SQL_PLAN_STATISTICS_ALL b where b.SQL_ID = a.SQL_ID)
  )
  start with PARENT_ID is null
  connect by prior ID = PARENT_ID
  order siblings by ID desc
)
order by NO desc
;

解説

  • 49行目のV$SQL_PLAN_STATISTICS_ALLが実行計画情報の取得元となり、50行目のWHERE条件で表示対象のSQL_IDで絞っている。(階層問い合わせでWHERE句を指定してもstart with~connect byの後に評価されるので、このビュー全件が表示対象となり非常に高負荷な問い合わせとなってしまう。)
  • 共有プールをフラッシュせずにこのスクリプトを実行させた場合、1つのSQL_IDに対して2つ以上のPLAN_HASH_VALUEが取得される場合がある。その際実行計画が正しく表示されない可能性があるので、51行目で直近のTIMESTAMPのものだけ1つを表示対象としている。
  • 53〜54行目は階層問い合わせによって、次のIdがNullとなるId=0を起点として実行順にId値をたどる。
  • 55行目のsiblings句により同じ階層(DEPTH)のId値を並び替えているが、desc[endant]を指定することでId値は逆実行順に並ぶ。ちなみに「siblings」とは「きょうだい」を意味する。
  • 35行目はNested Loops Joinにおいて実際の行数(A-Rows)と比較しやすいように見積もり行数(E-Rows)を加工している。(参考: 津島博士のパフォーマンス講座 第68回 TEMP領域の続きとA-Rowsについて
  • 29〜55行目の問い合わせにおいて、30行目のROWNUM疑似列で順序番号(NO列)を取得しているが、Id=0を先頭とした逆実行順の検索結果をNO列の降順に並び替えることで、実行順に表示させている。(当初はこの部分がなく下から順にたどっていく表示にしていたが、わかりやすさに欠けていたので改良した。)

表示結果

実行順実行統計出力スクリプトによって表示させた結果が以下である。

前回投稿の最後でこのSQLにおけるステップの実行順をまとめたが、以下の結果のID列の順序と一致していことを確認してほしい。

実行計画のステップがどんなに多くても、このスクリプトを使えば実行順に表示させることができる。

ID Operation                                         Name           Starts E-Rows A-Rows A-Time Buffers  Reads Writes  Srch Cols Pstart  Pstop PartID
-- ------------------------------------------------- -------------- ------ ------ ------ ------ ------- ------ ------ ---------- ------- ----- ------
 8         INDEX SKIP SCAN                           I_TABLE001_2        1 38,050  3,060   2.96    3619   1917      0          2
 7        TABLE ACCESS BY INDEX ROWID BATCHED        TABLE_001           1 38,046  3,060   3.12    3706   1977      0          0
11          INDEX RANGE SCAN                         I_TABLE004_8    3,060  3,060      1 204.17  117860 114690      0          5 KEY     KEY        9
10         TABLE ACCESS BY LOCAL INDEX ROWID BATCHED TABLE_004       3,060  3,060      1 204.19  117861 114691      0          0 KEY     KEY        9
 9        PARTITION RANGE ITERATOR                                   3,060  3,060      1 204.20  117861 114691      0          0 KEY     KEY        9
 6       NESTED LOOPS                                                    1      1      1 207.33  121567 116668      0          0
12       INDEX RANGE SCAN                            I_TABLE002PK        1      1      0   0.00       1      1      0          2
 5      NESTED LOOPS OUTER                                               1      1      1 207.34  121568 116669      0          0
 4     FILTER                                                            1      1      1 207.34  121568 116669      0          0
 3    FILTER                                                             1      1      1 207.34  121568 116669      0          0
 2   COUNT STOPKEY                                                       1      1      1 207.34  121568 116669      0          0
 1  SORT AGGREGATE                                                       1      1      1 207.34  121568 116669      0          0
 0 SELECT STATEMENT                                                      1      1      1 207.34  121568 116669      0          0

13行が選択されました。

経過: 00:00:00.02

A-Time列を上から順にたどっていき、値が急激に増えている箇所がボトルネックである。
この例ではId=11の「INDEX RANGE SCAN」がそれにあたる。

次回は、この結果から実際にどのようにチューニングを行なっていくかを追ってみる。

(続く)

実行統計による実践的SQLチューニング(その1)

この投稿は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」に設定

実行統計を取得するために3つの方法がある

  1. STATISTICS_LEVELパラメータをALLに設定する
  2. SQL文にGATHER_PLAN_STATISTICSヒントを指定し実行する
  3. 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を使用して、実行統計を併記した実行計画を表示させる。

9行目のDBMS_XPLAN.DISPLAY_CURSORと引数の設定がポイントである。

また、11行目は実行順に実行計画を表示させるスクリプトを呼び出している。(次回解説)

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が見積もった(1回あたりの)処理行数
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表示の経過時間と若干異なることに注意)

実行統計を併記するようにしても実行順を間違えるとボトルネックの判断を間違えてしまう可能性がある。
ということで、次回は実行計画を実行順に表示させる方法を紹介する。

今回はここまで