kagamihogeの日記

kagamihogeの日記です。

SQLトレースさわる

SQLトレースの取得

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス11g リリース2(11.2) DBMS_MONITOR

DBMS_MONITORパッケージを利用する。幾つかプロシージャがあるのだけど、DATABASE_TRACE_ENABLEプロシージャとSESSION_TRACE_ENABLEプロシージャが主に使うものだと思われる。この2つの違いはSQLトレースを取得対象とする範囲の違いで、前者はDB全体もしくはインスタンス単位、後者はセッション単位となっている。また、取得を停止するDISABLEプロシージャもそれぞれに対応する形で用意されている。

セッション単位

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス11g リリース2(11.2) DBMS_MONITOR.SESSION_TRACE_ENABLEプロシージャ

詳細は上記のリファレンスを参照。使い方はこんな感じ。

--現在のセッションでトレースを開始する。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE();
--セッションIDを指定してトレースを開始する。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(12);
--セッションIDとシリアルIDを指定してトレースを開始する。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(12, 133);

--バインド情報をトレースに含める。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(binds=>TRUE);
--待機情報をトレースに含める。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(waits=>TRUE);
--バインド情報と待機情報をトレースに含める。下記2つは同じ意味。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(binds=>TRUE, waits=>TRUE);
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(NULL, NULL, TRUE, TRUE);

--現在のセッションのトレースを停止する。
EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_DISABLE();

現行セッションでの取得はともかく。トレースを取得したいセッションの外からセッションIDを指定できるのは場合によっては便利そう。

DB全体もしくはインスタンス単位

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス11g リリース2(11.2) DBMS_MONITOR.DATABASE_TRACE_ENABLEプロシージャ

詳細は上記のリファレンスを参照。使い方は……まぁセッションの時とほとんど変わらないので例は省略。

ALTER SESSION SET SQL_TRACEとかALTER SESSION SET TIMED_STATISTICSとか

DBMS_MONITORパッケージは10g(未確認)くらいから導入されたらしく、それ以前のバージョンには存在しない。なので「SQLトレース」でぐぐったり参考文献見たりすると取得方法は下記のような感じで書かれている。

ALTER SESSION SET TIMED_STATISTICS = TRUE;
ALTER SESSION SET SQL_TRACE = TRUE;
--待機イベントの取得
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

別にコレでも出来ないことはないっぽいのだけど、待機の取得が謎めいた10046とかでマジで謎。なので明示的にパラメータで設定できるDBMS_MONITORを使った方が良いような気がする。

SQL Developerを使用したSQLトレースの取得

SQL DeveloperのGUIからトレースの取得開始をすることもできる。

ツール -> セッションのモニターを選ぶ。
f:id:kagamihoge:20140123183217p:plain
こんな感じにアクティブなセッションの一覧が表示される。

ので、SQLトレースを取得したいセッションを選択して右クリック。
f:id:kagamihoge:20140123183230p:plain
セッションのトレースを選択すると、下記のダイアログが表示される。このエントリの上の方で書いたのと同様なSQLになっていることが分かる。あとは適用ボタン押すだけ。
f:id:kagamihoge:20140123183235p:plain

ファイルの吐き出し場所の確認

初期化パラメータuser_dump_destで指定されたディレクトリにトレースファイルが出力される。

SELECT NAME, VALUE FROM v$parameter WHERE NAME = 'user_dump_dest';

ウチの11g XE環境では下記のディレクトリに出力されることになる。

NAME VALUE
user_dump_dest /u01/app/oracle/diag/rdbms/xe/XE/trace

トレースファイルの確認

とりあえず下記のような手順でSQLトレースを取得した、として以降は話を進める。

EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_ENABLE(BINDS=>TRUE, WAITS=>TRUE);

SELECT COUNT(*) FROM million_rows_table;
SELECT * FROM million_rows_table WHERE column_pk_int < :ID;

EXECUTE SYS.DBMS_MONITOR.SESSION_TRACE_DISABLE();
TKPROFによる整形

出力されたトレースファイル(*.trc)はそのままでは人間が読むには厳しいものがある。よって、TKPROFユーティリティによって整形を行う。コマンドラインの引数とかは下記のような感じらしい。

TKPROFはコマンド・ラインで“tkprof トレース・ファイル名 出力ファイル名 [SORT=パラメータ][PRINT=数値][EXPLAIN=ユーザー名/パスワード]”といった形式で実行します。
トラブル110番 - OracleのSQLトレースの取り方が分からない:ITpro

実行はこんな感じ。処理結果は3294.txtに出力される。

$ tkprof XE_ora_3294.trc EXPLAIN=kagamihoge/xxxx
output = 3294.txt

TKPROF: Release 11.2.0.2.0 - Development on 木 123 17:56:39 2014

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

出力結果の一部抜粋はこんな感じ。長ったらしいけど上から順に、実行したSQL・実行したSQLの統計情報いろいろ・実行計画・待機情報、となっている。

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

SQL ID: bfhu193kfrz51 Plan Hash: 1047193584

SELECT * 
FROM
 million_rows_table WHERE column_pk_int < :ID


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       40      0.00       0.00          9         93          0        1999
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       42      0.00       0.00          9         93          0        1999

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48  (KAGAMIHOGE)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1999       1999       1999  TABLE ACCESS BY INDEX ROWID MILLION_ROWS_TABLE (cr=93 pr=9 pw=0 time=10067 us cost=15 size=51974 card=1999)
      1999       1999       1999   INDEX RANGE SCAN MILLION_ROWS_TABLE_PK (cr=45 pr=0 pw=0 time=3800 us cost=6 size=0 card=1999)(object id 21359)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
   1999   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
              'MILLION_ROWS_TABLE' (TABLE)
   1999    INDEX   MODE: ANALYZED (RANGE SCAN) OF 'MILLION_ROWS_TABLE_PK' 
               (INDEX (UNIQUE))


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      40        0.00          0.00
  db file sequential read                         9        0.00          0.00
  SQL*Net message from client                    40        2.33          2.41



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

SQL Developerによる表示

TKPROFで整形しない方法としてSQL Developerがある。ナマのtrcファイルをそのままSQL Developerにドラッグ&ドロップするか、ファイル -> 開く、をするだけ。イメージ的には下記のような感じ。
f:id:kagamihoge:20140123183722p:plain
ソートがカンタンに出来るし、統計と待機をセットで流し見していけるので、SQLの件数が多い場合にはこっちのほうが便利かもしれない。
しかし、日本語がビミョーなのが気になるんだよなぁ……昇順の逆が説明になってるのかなり謎。ソートはディスクなのに、一覧では物理になってたりも謎めいている。