実行計画を取得する！

これまでの経験上、Oracle パフォーマンス問題の原因として一番多いのは、やはり SQL です。
ということで、SQL チューニングで役立つネタを紹介していこうかと思います。

今回は SQL チューニングに必要な準備として実行計画の取得方法をご紹介します。

実行計画の取得方法

SQL の実行計画を取得する方法は以下のようにいくつかあります。

SQLトレース（tkprof）
EXPLAIN PLAN（パースするが、実行はしない）
AUTOTRACE（SQL*Plus の機能。SQL を実行して実行計画や統計情報を出力）
DBMS_XPLAN.DISPLAY_CURSOR (ライブラリキャッシュの共有カーソルを表示。パースしない)
STATSKPACK / AWRのSQLレポート

[参考] @IT　- SQLチューニングの基盤となる統計情報 –
http://www.atmarkit.co.jp/ait/articles/0410/21/news098.html

実践上、SQL が複雑で実行計画だけを見て直ぐにボトルネックを特定できないような高難度の SQL チューニングの場合は、やはり SQLトレースを取得するのが一番です。

実際に SQL を実行する必要があったり、取得方法が面倒だったりデメリットはあるものの、それを補って余りある情報の取得が可能です。

SQLトレース使用例

以下、実際に SQLトレースの取得と tkprof による整形を行う例を記載します。

なお SCSK 株式会社は、本ドキュメントの使用の結果生じるいかなる損害についても、責任を負いかねますのでご了承ください。本番環境で実施する際には、十分検証してからの実施を推奨します。

1. サンプルテーブルの作成

SQL> --商品表を作成
SQL> create table item
　2  (
　3 　 item_no number,
　4 　 item_name varchar2(100)
　5  )
　6  ;

表が作成されました。

SQL> alter table item add constraint pk_item primary key(item_no);

表が変更されました。

SQL>--商品明細表を作成
SQL> create table item_detail
　2  (
　3 　 item_no number,
　4 　 item_detail_no number,
　5 　 item_detail_name varchar2(100)
　6  )
　7  ;

表が作成されました。

SQL> alter table item_detail add constraint pk_item_detail primary key(item_no,item_detail_no);

表が変更されました。

2. サンプルデータの作成

SQL> --商品に1000件、商品明細に10000000件データをinsert
SQL> @cr_data.sql
SQL> set serveroutput on
SQL> set echo on
SQL> DECLARE
　2 　 cnt_item number:=0;
　3 　 cnt_item_detail number:=0;
　4  BEGIN
　5 　 FOR i IN 1..1000 LOOP
　6 　　 insert into item values (i,'ITEM NAME');
　7
　8 　 　FOR j IN 1..10000 LOOP
　9 　　　 insert into item_detail values (i,j,'ITEM DETAIL NAME');
 10 　　 END LOOP;
 11 　　 commit;
 12
 13 　 END LOOP;
 14 　 select count(*) into cnt_item from item;
 15 　 dbms_output.put_line(cnt_item);
 16 　 select count(*) into cnt_item_detail from item_detail;
 17 　 dbms_output.put_line(cnt_item_detail);
 18　END;
 19　/
 1000
 10000000

 PL/SQLプロシージャが正常に完了しました。

3. SQLトレース取得（サンプルクエリ実行）

SQL> @sample_query.sql
SQL> set timing on
SQL>
SQL> --SQLトレース(レベル12)の取得を開始
SQL> alter session set events '10046 trace name context forever, level 12';

セッションが変更されました。

SQL> select
　2 　 a.item_no
　3 　,b.item_detail_name
　4 　,count(*) cnt
　5  from
　6 　 item a
　7 　,item_detail b
　8  where
　9 　 a.item_no = b.item_no
 10  group by
 11 　 a.item_no
 12 　,b.item_detail_name
 13 ;

 ITEM_NO ITEM_DETAIL_NAME　　 CNT
-------- -------------------- -----
　　 654 ITEM DETAIL NAME 　　10000
　　　　・・・<中略>・・・
　　 417 ITEM DETAIL NAME 　　10000

1000行が選択されました。

経過: 00:00:12.46 　★実行に約12秒かかっている

SQL> --SQLトレースを停止。
SQL> alter session set events '10046 trace name context off'; 

セッションが変更されました。

SQL> --トレースファイル名の一部(OSのPID)を取得
SQL> select
　2 　 s.sid
　3 　,p.spid
　4  from
　5 　 v$session s
　6 　,v$process p
　7  where
　8 　 s.paddr = p.addr
　9  and 
 10　　s.audsid = userenv('SESSIONID')
 11 ;

SID SPID
--- ----------
146 19850
　　~~~~~ ★今回は19850

4. tkprof ユーティリティで SQLトレースのトレースファイルを整形

-bash-3.2$ tkprof /u01/app/oracle/diag/rdbms/scsp0/SCSP1/trace/SCSP1_ora_19850.trc result.prof sys=no sort=exeela
　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　 ★3．で確認した OSPID を含むトレースファイルを指定

5. 実行計画の確認

【サマリセクション】

サマリセクションで大まかな SQL の処理時間などを把握します。

-bash-3.2$ cat result.prof
********************************************************************************
select
　 a.item_no
　,b.item_detail_name
　,count(*) cnt
from
　 item a
　,item_detail b
where
　 a.item_no = b.item_no
group by
　 a.item_no
　,b.item_detail_name

call　　 count　　　cpu　　elapsed　　　disk　　query current　rows
------- ------ -------- ---------- --------- -------- ------- -----
Parse　　　　1 　　0.06 　　　0.07 　　　 32 　　1708 　　　5 　　0
Execute　　　1 　　0.00 　　　0.00　　　　 0 　　　 0 　　　0 　　0
Fetch　　　 68 　　7.48 　　 11.99　　 22034 　 65575 　　　0  1000
------- ------ -------- ---------- --------- -------- ------- -----
total 　　　70 　　7.54 　　 12.07 　　22066 　 67283 　　　5  1000

行説明

Parse	パース(解析)
Execute	実行
Fetch	フェッチ(データの取り出し)

列説明

count	実行回数
cpu	CPU時間(秒)
elapsed	経過時間(秒)
disk	物理読み込みブロック数
query	一貫性モードで読み込まれたバッファブロック数 (主に SELECT での読み込み）
current	カレントモードで読み込まれたバッファブロック数 (主に INSERT、UPDATE、DELETE での読み込み）
rows	SQL 文によって処理された行の総数 (副問い合わせなどの処理数は含まれない）

上記の例では、elapsed が 12.07 秒のため、SQL の実行に 12.07 秒、うち Parse に0.07 秒、データの取り出しに11.99 秒かかっていることがわかります。そのため、ほとんどの実行時間をデータの取り出しに要している状況です。
データの取り出しは disk が 22034 ブロックのため、1ブロック 8kで計算した場合、22034 × 8k ≒ 180MB が物理Read されていることになります。

【実行計画セクション】

実行計画セクションでは SQL の実行計画が出力されます。
SQLトレースのよいところは、実行計画のステップ毎にそのステップに要した実行時間が分かる点です。

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1

　　Rows (1st) Rows (avg) Rows (max) Row Source Operation
　　---------- ---------- ---------- ---------------------------------------------------
⑦　　　　1000 　　　1000 　　　1000 HASH GROUP BY (cr=65575 pr=22034 pw=0 time=11995029 us cost=11959 size=835293520 card=10441169)
⑥　　　　1000 　　　1000 　　　1000 　NESTED LOOPS (cr=65575 pr=22034 pw=0 time=11371562 us cost=10614 size=835293520 card=10441169)
①　　　　1000 　　　1000 　　　1000 　　　INDEX FAST FULL SCAN PK_ITEM (cr=7 pr=0 pw=0 time=648 us cost=3 size=13000 card=1000)(object id 76699)
⑤　　　　1000 　　　1000 　　　1000 　VIEW PUSHED PREDICATE VW_GBF_7 (cr=65568 pr=22034 pw=0 time=11805165 us cost=11 size=6968 card=104)
④　　　　1000 　　　1000 　　　1000 　　SORT GROUP BY (cr=65568 pr=22034 pw=0 time=11803723 us cost=11 size=6786780 card=104412)
③　　10000000 　10000000 　10000000 　　　TABLE ACCESS BY INDEX ROWID ITEM_DETAIL (cr=65568 pr=22034 pw=0 time=11871956 us cost=0 size=6786780 card=104412)
②　　10000000 　10000000 　10000000 　　　INDEX RANGE SCAN PK_ITEM_DETAIL (cr=24378 pr=0 pw=0 time=2098638 us cost=0 size=0 card=41765)(object id 76701)

上記の例では、①～⑦ の順でステップが実行されます。
③ の実行時間が time=11871956（マイクロ秒）のため、約11.8 秒要していることがわかります。
また ② までは time=2098638 と約2.1秒です。そのためステップ ③ の実行時間は ③ – ② ≒ 9.7 秒となります。

全体のデータの取り出しに掛かる時間は上述のとおり 11.99 秒のため、ステップ ③ で全体の実行時間の約80%（9.7/11.99≒0.8割）を占めている状態です。

つまり ③ のステップがこの SQL が遅い原因のほとんどを占めており、逆このステップを改善することが出来れば、この SQL を劇的に速くできることがわかります。

【待機イベントセクション】

レベル12で SQLトレースを取得すると、SQL が待機したイベントとその待機時間が出力されます。

Elapsed times include waiting on following events:
　Event waited on　　　　　　　　　　　　 　Times Max. Wait　Total Waited
　---------------------------------------- Waited ---------- ------------
　row cache lock 　　　　　　　　　　　　　　　 1 　　　0.00 　　　　0.00
　SQL*Net message to client 　　　　　　　　　 68 　　　0.00 　　　　0.00
　db file sequential read 　　　　　　　　　22034 　　　0.00 　　　　4.91
　SQL*Net message from client 　　　　　　　　 68 　　　0.34 　　　　0.37

********************************************************************************

上記の例では、 db file sequential read で 4.91 秒待機しています。

db file sequential read は主に INDEX の単一ブロックに対する物理読み込み時に I/O 待機した時間がカウントされます。
上述のステップ ③ を見ると、このステップは INDEX 読み込み（TABLE ACCESS BY INDEX ROWID）をしています。
pr=22034 となっているため、22034 ブロックはキッシュではなくディスク（データファイル）から読み込んでいることがわかります。
待機イベントの状況から、その時に待機した時間が 4.91 秒と推測できます。
そのため、この INDEX がキャッシュに乗ってれば、それだけで約 4.91 秒は改善されると考えられます。

このようにSQLトレースでは、実行計画のステップ毎の実行時間やSQL実行時の待機イベントの時間が分かるため、他の実行計画取得方法より多くの情報を取得でき、SQLボトルネック箇所を特定しやすいです。

取得は面倒ですが、慣れればそれほど苦ではないので、是非試してみて下さい。