MySWL×SCSK

MySQL ClusterをはじめとするHAソリューションなど、
SCSKが最先端の技術力でソリューションを提供します

見積依頼 資料ダウンロードはこちら

TOPICS

[OracleDB] 実行計画を取得する!

 これまでの経験上、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を実行する必要があったり、取得方法が面倒だったりデメリットはあるものの、それを補って余りある情報の取得が可能です。


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

【使用例】

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

    --商品表
    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. サンプルデータの作成

    --商品に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> @sample_query.sql
    SQL> set timing on
    SQL>
    SQL> alter session set events '10046 trace name context forever, level 12'; ←トレース取得開始。Lv12で待機イベントまで取得できる。

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

    経過: 00:00:00.01
    SQL>
    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> alter session set events '10046 trace name context off'; ←トレース取得開始

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

    経過: 00:00:00.00
    SQL>
    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 s.audsid = userenv('SESSIONID')
    10 ;

    SID SPID
    ---------- ------------------------
    146 19850 ←トレースファイル名の一部(OSのPID)を取得。今回は「19850」

    経過: 00:00:00.01


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

    -bash-3.2$ tkprof /u01/app/oracle/diag/rdbms/scsp0/SCSP1/trace/SCSP1_ora_19850.trc result.prof sys=no sort=exeela
    ↑PID「19850」で出力されたトレースファイル


5. 実行計画の確認

    -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

    【サマリセクション】
    ■行説明
    Parse :パース
    Execute:実行
    Fetch :フェッチ(データの取り出し)

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

    ※このセクションで大まかなSQLの処理時間などを把握する。
    ※上記の例では、elapsedが12.07秒なので、SQLの実行に12.07秒、内Parseに0.07秒、データの取り出しに11.99秒
    掛かっていることが分かる。
    ※ほとんどがデータの取り出しに時間を要しており、diskが22034ブロックなので、1ブロック8kだと
    22034×8k≒180MBが物理Readされていることになる。

    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


    【実行計画セクション】
    ※このセクションではSQLの実行計画が出力される。
    ※SQLトレースのよいところは、実行計画のステップ毎に、そのステップに要した実行時間が
    分かる点である。
    ※下記の例では、①~⑦の順でステップが実行されるが、③の実行時間が time=11871956(マイクロ秒)なので、
    約11.8秒要していることが分かる。②まではtime=2098638なので、約2.1秒であると考えると、ステップ③での
    実行時間は③-②≒9.7秒となる。

    全体のデータの取り出しに掛かる時間は上述のとおり11.99秒なので、ステップ③で全体の実行時間の約80%(9.7/11.99≒0.8割)
    を占めていることが分かる。
    ⇒つまり③のステップがこの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)


    【待機イベントセクション】
    ※Lv12でトレースを取得すると、このSQLで待機したイベントとその待機時間が出力される。
    ※下記の例では、「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秒は改善されることを意味する。

    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

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


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

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

SCSKだから選ばれる

10年以上にわたるMySQLの取り組み

10年以上にわたるMySQLの取り組み

MySQLオフィシャルトレーニングを多数担当。日本オラクル社のパートナー認定制度「MySQL Specialization」国内第1号取得。オリジナル全文検索ソリューション開発

SCSKの強み

SCSKの強み

オフィシャルトレーニング資格を有する技術者が提供する高い技術力。大規模通信系システム、大規模基幹系システムなども経験。国内企業数百社に対する導入実績。MySQLに関連する全てのサービスをワンストップで提供

お問い合わせ

MySQLやMySQL関連ソリューションに関するお問い合わせ、資料請求、お見積、ご相談などございましたら、こちらよりご連絡下さいませ。

お問い合わせ資料ダウンロード見積依頼

OracleとJavaは、Oracle Corporation 及びその子会社、関連会社の米国及びその他の国における登録商標です。文中の社名、商品名等は各社の商標または登録商標である場合があります。