*以下は、サポート契約締結中のお客様に2015年3月号として配信しているサポートレターより一部抜粋して掲載しています。

皆様は、特定の SQL 文によってアプリケーションのパフォーマンスが低下したという経験はありませんか。パフォーマンスが低下した際、SQL トレースを用いることで SQL 文の効率を正確に評価でき、パフォーマンス低下の原因となっている SQL 文を特定することができます。

SQL トレースの出力結果（以下、生トレース）を直接解析することは稀です。通常は、生トレースを tkprof ユーティリティを用いて見やすく整形（以下、整形済みトレース）してから解析します。

そこで今回は、SQL トレースの概要および取得方法を説明しつつ、生トレースを見ることが有益なケースをご紹介します。

SQL トレースで得られる情報

まず、SQL トレースでどういった情報が得られるかをご紹介します。

SQL_TRACE 初期化パラメータを TRUE に設定すると、以下のような情報が得られます。

• 解析、実行、フェッチのカウント
• CPU 時間と経過時間
• 物理読取りと論理読取り
• 処理された行数
• ライブラリ・キャッシュでのミス
• それぞれの解析が行われるユーザー名
• 各コミットおよびロールバック
• 各 SQL 文の待機イベント・データおよび各トレース・ファイルの要約
• 各 SQL 文の実際の実行計画を示す行操作
• 行数、一貫性のある読取りの数、物理読取り数、物理書込み数および行の各操作の経過時間

• ※ 処理時間を出力する場合は、TIMED_STATISTICS 初期化パラメータが TRUE である必要があります。

イベント 10046（ SQL トレースを収集するためのイベント）や DBMS_MONITORパッケージ（10g～）を用いると、さらに詳細な情報を取得することが可能です。
イベント 10046 では以下のように、指定するレベルによって出力される情報が異なります。

• レベル 1 → 通常の SQL トレースと同じ出力（デフォルト）
• レベル 4 → バインド変数の情報を含む
• レベル 8 → 待機イベントの情報を含む
• レベル 12 → バインド変数および待機イベントの情報を含む

SQL トレースの取得手順

次に、具体的な SQL 文を交えつつ、SQL トレースを取得し、tkprof ユーティリティで整形する手順をご説明します。

• ※ 以降では、Oracle Database のバージョンは 11gR2 であることを前提とします。

通常、以下のステップで整形済みトレースを取得します。

• Step1) 事前準備
• Step2) SQL トレースを開始する
• Step3) SQL 文を実行する
• Step4) SQL トレースを終了する
• Step5) 出力結果（生トレース）を tkprof ユーティリティで整形する

各ステップについて説明していきます。

Step1) 事前準備

今回の例では、scott ユーザ^（※1）にて、以下のような表^（※2）を用います。主キー列 id （ 1 から 1,000,000 までの連番を格納）と name 列（ランダムな 10 桁の文字列を格納）からなる 1,000,000 行の表を用意しました。

SQL> select * from trace_test;

ID NAME
---------- ----------
1 OFWBWOxDjk
2 qMmzGJURgj
3 IptXbqDxYg

（中略）

1000000 LBLPIMqjTj

1000000行が選択されました。

また、scott ユーザで SQL トレースを取得できるよう、事前に sys ユーザにて、scott ユーザに alter session 権限を付与しておきます。

SQL> grant alter session to scott;

• ※1 scott ユーザが存在しない場合、sys ユーザにて以下の SQLファイル を実行することでscott ユーザ（パスワードは tiger ）を作成できます。

$ORACLE_HOME/rdbms/admin/utlsampl.sql

• ※2 今回の表は以下の SQL で用意しました。

SQL> create table trace_test (
id integer primary key,
name varchar2(10)
);
SQL> insert /*+ APPEND */ into trace_test nologging (
select
rownum, DBMS_RANDOM.STRING('A', 10)
from
(select 0 from all_catalog where rownum <= 1000),
(select 0 from all_catalog where rownum <= 1000)
);
SQL> commit;

Step2) SQL トレースを開始する

今回は、scott ユーザにて、レベル 12 のイベント 10046 によって SQL トレースを取得します。

SQL> conn scott/tiger
SQL> alter session set events '10046 trace name context forever, level 12';

Step3) SQL 文を実行する

以下の SQL 文を実行するものとします。

SQL> var max_id number;
SQL> exec :max_id := 800000;
SQL> select * from trace_test where id < :max_id;="" sql=""> exec :max_id := 2;
SQL> select * from trace_test where id < :max_id;="">

バインド変数 max_id に異なる値を代入し、同一の select 文を実行しています。
select 文では、max_id よりも小さい id を持つ行を取得します。

Step4) SQL トレースを終了する

イベント 10046 による SQL トレースを終了します。

SQL> alter session set events '10046 trace name context off';

ここまでで、以下のディレクトリ配下に生トレースが生成されています。

DIAGNOSTIC_DEST/diag/rdbms/DB_NAME/SID/trace/

いずれのトレースファイルがこのセッションで取得されたものかは、以下の SQL 文により特定できます。

SQL> select value from v$diag_info where name='Default Trace File';

VALUE
-------------------------------------------------------
/u01/app/diag/rdbms/orcl/orcl/trace/orcl_ora_6664.trc

Step5) 出力結果を tkprof ユーティリティで整形する

Step4 までで取得した生トレースを tkprof ユーティリティを用いることで整形し、SQL 文と実行計画、統計を見やすくします。今回は以下のように sys=no を指定して実行します。

$ tkprof /u01/app/diag/rdbms/orcl/orcl/trace/orcl_ora_6664.trc trace_test.prof sys=no

• ※ sys=no を指定することで、SYS ユーザで実行された SQL 文（再帰的 SQL 文など）を除外することができ、ユーザ実行の SQL 文のみをリストします。デフォルトは sys=yes です。

このコマンドにより、trace_test.prof というファイル名の整形済みトレースが出力されます。

整形済みトレースを見る

まず、整形済みトレースにて Step2 で実行した SQL 文に関する出力を探します。（下の例は見やすいように一部加工しています。）

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

SQL ID: ac5d76qah8mhj Plan Hash: 3717688840

select *
from
trace_test where id < :max_id

call count cpu elapsed disk query current rows
------- ------ ------ ---------- --------- ---------- ---------- --------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 4 1 0
Fetch 53337 0.58 1.70 5812 58998 0 800000
------- ------ ------ ---------- --------- ---------- ---------- --------
total 53341 0.58 1.70 5812 59002 1 800000

(略)
☆ Rows (1st) Rows (avg) Rows (max) Row Source Operation
☆ ---------- ---------- ---------- -----------------------------------------
☆ 799999 400000 799999 TABLE ACCESS FULL TRACE_TEST (cr=29499
☆ pr=2906 pw=0 time=713738 us cost=810 size
☆ =15526520 card=776326)
(略)
***************************************************************************

実際に採用された実行計画（☆部分）を見てみると、2 つの select 文が集計されており、ともに全表操作（ TABLE ACCESS FULL ）が選択されたことが分かります。しかし、取得されている行数は平均 400,000 行、最大 799,999 行と、大きな偏りがあります。

このように、tkprof ユーティリティで SQL トレースを整形すると、SQL テキストおよび実行計画が同一の SQL 文に関して重複が排除される^（※3）ので、出力量が少なくなり見やすくなります。しかし、上記の例のようにバインド変数の値が異なる SQL 文も集計されてしまうため、バインド変数の値ごとの SQL 文のパフォーマンスは見ることはできません。

• ※3 tkprof 実行時に aggregate=no を指定することで SQL 文を集計しないようにすることも可能です。しかし、トレースファイルを見やすく整形するという tkprofユーティリティを使用するメリットが薄れてしまいます。また、それぞれの SQL 文でバインド変数にどの値が代入されているかまでは出力されません。

生トレースを見る

以上のように、整形済みトレースでは個別の SQL 文のパフォーマンスが評価できない場合もあり、その場合は生トレースを見る必要があります。

生トレースには、整形済みトレースの情報に加えて、バインド変数、再帰的 SQL 文（ tkprof 実行時に sys=no を指定した場合）に関する情報が含まれています。

今回は、以下の出力に着目します。

=====================
PARSING IN CURSOR #140341079458648 len=43 dep=0 uid=93 oct=3 lid=93
tim=1426139770141121 hv=2500087313 ad='a1fd3f88' sqlid='ac5d76qah8mhj'
☆1 select * from trace_test where id < :max_id
END OF STMT
PARSE #140341079458648:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,
plh=1558085358,tim=1426139770141121
BINDS #140341079458648:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7fa3b4303f10 bln=22 avl=02 flg=05
☆2 value=2
EXEC #140341079458648:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,
plh=1558085358,tim=1426139770141168
WAIT #140341079458648: nam='SQL*Net message to client' ela= 1 driver
id=1650815232 #bytes=1 p3=0 obj#=89692 tim=1426139770141195
(略)
FETCH #140341079458648:c=0,e=124,p=13,cr=4,cu=0,mis=0,r=1,dep=0,og=1,
plh=1558085358,tim=1426139770141329
(略)
☆3 STAT #140341079458648 id=1 cnt=1 pid=0 pos=1 obj=89692 op='TABLE ACCESS
FULL TRACE_TEST (cr=2910 pr=2906 pw=0 time=119 us cost=810 size=15526520
card=776326)'
(略)
CLOSE #140341079458648:c=0,e=0,dep=0,type=0,tim=1426139770157388
=====================

生トレース中の各行は以下を意味しています。

☆1 から分かるように、これは Step3 で実行した SQL 文に関する出力です。「PARSING IN CURSOR」に続く「#140341079458648」という数字がカーソル番号です。生トレースは時系列に出力されるので、複数のセッションから同時に SQL 文を実行すると、それぞれの SQL 文に対するトレースが入り乱れてしまいます。そのため、カーソル番号が同じ出力を紐付けていく必要があります。

カーソル番号が同じ出力のうち、☆2 を見ることで、バインド変数 max_id が 2 であるときの出力であることが分かります。採用された実行計画（☆3）を見ると、処理行数が1 行である（cnt=1）のに対して、読み込んだブロック数が大きい（cr=2910 pr=2906）ことが分かります（※4）。

• ※4 ここで、各文字列は以下を意味しています。

この場合、バインド変数が異なる 2 つの select 文で同じ実行計画が採用されていることで、一方の select 文では最適でない実行計画が選択されていることが示唆されます。

まとめ

今回は SQL トレースに関して、tkprof ユーティリティを使用した整形済みトレースよりも整形前の生トレースを見ると有益である例をご紹介しました。tkprof ユーティリティを用いると、ユーザ実行の SQL 文のパフォーマンスを分析しやすくなりますが、集計、排除されてしまう情報もあるため、生トレースを分析する必要が生じる場合もあります。
場合によっては、生トレースの分析をご検討ください。

参考情報

• Oracle Databaseパフォーマンス・チューニング・ガイド 11gリリース2 (11.2)

(オラクル事業部 技術担当サポートセンターG 石原)

• Oracle関連サービス