小さい頃はエラ呼吸

いつのまにやら肺で呼吸をしています。


デバッグに便利!OracleのSQLトレースログを出力する方法

Oracle
はじめに

Oracle Databaseを使ったアプリケーション開発で、Oracleが実行したSQLをログ出力して確認したいときがあります。
Oracleのトレースログを有効にすると、実行したSQLをログに吐き出してあとから確認することができます。

新・門外不出のOracle現場ワザ エキスパートが明かす運用・管理の極意 (DB Selection)
新・門外不出のOracle現場ワザ エキスパートが明かす運用・管理の極意 (DB Selection)
posted with amazlet at 13.01.10
小田 圭二 大塚 信男 五十嵐 建平 谷 敦雄 宮崎 博之 神田 達成 村方 仁
翔泳社
売り上げランキング: 145,950
Amazon.co.jp で詳細を見る

トレースログの出力場所を確認する

はじめにsysユーザで接続して、トレースログの出力場所を確認します。
以下のコマンドを実行すると、トレースログがどこに出力されるかを確認することができます。

conn sys/oracle as sysdba
SHOW PARAMETER USER_DUMP_DEST

NAME                                 TYPE                   VALUE
------------------------------------ ---------------------- ------------------------------
background_dump_dest                 string                 C:\oraclexe\app\oracle\diag\rdbms\xe\xe\trace

ぼくの環境（Oracle 11g Express Edition）では、C:\oraclexe\app\oracle\diag\rdbms\xe\xe\traceに出力されるようになっていました。

トレースログの出力を有効にする

トレースログを有効にするには、以下のコマンドを実行します。これにより、すべてのセッションでトレースログが出力されるようになります。

ALTER SYSTEM SET SQL_TRACE = TRUE;
トレースログを見てみる

トレースログを有効した状態で、oracleのテーブル一覧を表示してみます。

SELECT TABLE_NAME FROM USER_TABLES;

トレースログ出力ディレクトリ配下にxxx.trcというファイルができています。このファイルをテキストエディタで表示してみます。

PARSING IN CURSOR #274504288 len=34 dep=0 uid=50 oct=3 lid=50 tim=4915183425 hv=4041002574 ad='296ad7f8' sqlid='64qgr0gsdtmkf'
SELECT TABLE_NAME FROM USER_TABLES←★
END OF STMT

一番下のほうに、さきほど実行したSQLが表示されていますね。

バインド変数を含むSQLの場合

次に、バインド変数を使ったSQLを実行してみます。

variable v1 VARCHAR2(20);
execute :v1 := 'TABLE01'
SELECT TABLE_NAME FROM USER_TABLES WHERE TABLE_NAME = :v1;

トレースログに実行したSQLは出力されていますが、バインド変数が展開されていません。これでは、実行時にv1に何が格納されていたのかがわかりませんね。

PARSING IN CURSOR #274504288 len=57 dep=0 uid=50 oct=3 lid=50 tim=5280246169 hv=232826063 ad='296a88f8' sqlid='3as2vpw6y196g'
SELECT TABLE_NAME FROM USER_TABLES WHERE TABLE_NAME = :v1
END OF STMT

トレースログにバインド変数を出力する

トレースログにバインド変数を出力するには、以下のコマンドを実行します。

ALTER SYSTEM SET EVENTS '10046 trace name context forever, level 4';

これは、10046イベントのレベルを４にしています。これにより、トレースログにバインド変数が出力されるようになります。レベルには以下の４種類があります。

Level 1 -> SQLトレースだけ
Level 4 -> SQLトレースとバインド変数
Level 8 -> SQLトレースと待機イベント
Level 12 -> SQLトレースとバインド変数と待機イベント
SQL Trace を取得する方法 - DBMS_SYSTEM - SQL> shutdown abort はてなブックマーク - SQL Trace を取得する方法 - DBMS_SYSTEM - SQL> shutdown abort

もう一度さきほどのSQLを実行してみると、BINDSというログが出力され、valueの部分に展開された値が出力されます。

PARSING IN CURSOR #258989348 len=57 dep=0 uid=0 oct=3 lid=0 tim=5711701251 hv=232826063 ad='296a88f8' sqlid='3as2vpw6y196g'
SELECT TABLE_NAME FROM USER_TABLES WHERE TABLE_NAME = :v1
END OF STMT
PARSE #258989348:c=0,e=14714,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2777635855,tim=5711701245
BINDS #258989348:
Bind#0
oacdty=01 mxl=128(60) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=128 off=0
kxsbbbfp=0f6fd81c bln=128 avl=07 flg=05
value="TABLE01"←これがバインド変数の中身

トレースログの設定を元に戻す

最後にトレースログを元に戻す方法も書いておきます。

  • 10046イベントを元に戻す
ALTER SYSTEM SET EVENTS '10046 trace name context off';
  • トレースログの出力を無効にする
ALTER SYSTEM SET SQL_TRACE = FALSE;

関連エントリ