SQLトレースの解析
本ページではtkprofで整形したSQLトレースの解析方法を記載します。出力項目の説明
以下の11.2で出力されたSQLトレースを例に項目の説明を記載します。
********************************************************************************
SQL ID: c99yw1xkb4f1u ①
Plan Hash: 1357081020 ②
select * ③
from
test
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 2 0.00 0.00 0 7 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 7 0 1
Misses in library cache during parse: 1⑫
Optimizer mode: ALL_ROWS⑬
Parsing user id: 86 ⑭
Rows⑮ Row Source Operation⑯
------- ---------------------------------------------------
1 TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=0 us cost=3 size=3 card=1)
********************************************************************************
| NO | 説明 |
|---|---|
| ① | SQL_ID。SQL_IDはSQL文のハッシュ値のようなものでSQL文が同じであれば実行スキーマが異なったり、バインド変数の値が違っていても同じSQLIDが割り当てられる。 また、現状(11.2が最新バージョン)ではバージョンが異なっても同じSQL文は同じSQL_IDとなる |
| ② | 実行計画のハッシュ値。SQLIDが同じでも複数の子カーソルを持っていれば実行計画は異なる可能性がある |
| ③ | SQL文 |
| ④ | コールの種別。Parse=解析、Execute=実行、Fetch=フェッチ |
| ⑤ | 実行回数 |
| ⑥ | CPU使用時間(秒) |
| ⑦ | 経過時間(秒)。この値には⑥も含まれる |
| ⑧ | 物理ディスクからバッファキャッシュに読み込んだブロック数 |
| ⑨ | 読み取り一貫性(Consistent Read)モードでバッファから読み込んだブロック数で⑧の一部またはすべてが含まれる。主にクエリで読み込むブロックが該当する |
| ⑩ | カレントモードでバッファから読み込んだブロック数で⑧の一部またはすべてが含まれる。主にDML文で更新するブロックが該当する |
| ⑪ | 行数。DML文等での更新行数はExecuteに計上され、クエリで戻される行数はFetchに計上される |
| ⑫ | パース時にライブラリキャッシュにヒットせずハードパースされた回数。 |
| ⑬ | オプティマイザモード。オプティマイザモードは実行計画を立てる基本方針で初期化パラメータoptimizer_modeやヒント等で変更することができる |
| ⑭ | パースを実行したユーザID。ユーザIDはdba_usersのUSER_IDなどで確認ができる |
| ⑮ | 各オペレーションが戻した行数 |
| ⑯ | Row Source Operationは実際に実行したときの実行計画及び統計を表す。Execution Planと表示されている場合はtkprofで接続したインスタンスが作成した実行計画であり実際に実行された実行計画と同じではない可能性がある。
またカッコ内の項目は以下を表している。 cr・・・Consistent Read(読み取り一貫性)モードのブロック読み込み数 pr・・・Phisical Read(物理DISKからの読み込みブロック数) pw・・・Phisical Write(物理DISKへの書き込みブロック数) time・・・経過時間。単位はus(マイクロ秒) cost・・・統計情報から算出したコスト size・・・統計情報から算出した平均行サイズ card・・・統計情報から算出したcardinality(選択率) |
SQLトレースからのSQLパフォーマンス調査
基本的には以下のような観点で調査を行います。1 チューニング対象SQLの特定
時間がかかる処理ほどチューニング効果が高いため処理時間(elapsed)が長いSQLをSQLトレースから特定します。 また、デフォルトのtkprofの動作は同じSQL文をサマリして出力するため実行毎に処理時間が大きく異なるような状況の場合はAGGREGATE=NOを指定して個別に出力させます。
2 処理時間の内訳を確認する
着目したSQLのどこで時間がかかっているのかを確認するため、該当のSQLに対して処理時間に対するCPU時間(cpu)の比率を確認します。 処理時間に対してCPU時間の比率が少ない場合、ロックなどにより何かしらの待機イベントでの待機が発生している可能性があるためこの場合は待機イベントも合わせて確認する必要があります。
待機イベントはDBMS_MONITOR.SESSION_TRACE_ENABLEパッケージでwaits=>TRUEを指定してトレースを有効にするとSQLトレースに待機イベントを追加記録することができます。
3 実行計画の見直し
CPU時間の比率が高い場合やアクセス対象のセグメントへの物理DISK読み込み、書き込みで処理時間が長くなっている場合は実行計画が最適であるか見直します。 実行計画上どの箇所で時間がかかっているかはRow Source Operationで表示される各行のtime値より確認することができます。
各バージョンのSQLトレース出力例
バージョンによってSQLトレースのRow Source Operationには出力内容に差異があり、10gでは Row Source Operationの各行に対する読み込みブロック数、DISK読み込みブロック数、実行時間が追加され、 11gではさらに統計情報のコスト、平均行サイズ、カーディナリティが追加され解析しやすくなっています。11.2
********************************************************************************
SQL ID: c99yw1xkb4f1u
Plan Hash: 1357081020
select *
from
test
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 2 0.00 0.00 0 7 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 7 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 86
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=0 us cost=3 size=3 card=1)
********************************************************************************
11.1
********************************************************************************
select *
from
test
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 2 0.00 0.00 0 249 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 249 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 82
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL TEST (cr=249 pr=0 pw=0 time=0 us cost=68 size=3 card=1)
********************************************************************************
10.2
********************************************************************************
select *
from
test
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 2 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 3 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 27
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL TEST (cr=3 pr=0 pw=0 time=62 us)
********************************************************************************
10.1
********************************************************************************
select *
from
test
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 7 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 8 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 57
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=29 us)
********************************************************************************
9.2
********************************************************************************
select *
from
test
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.00 0 4 0 2
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 39
Rows Row Source Operation
------- ---------------------------------------------------
2 TABLE ACCESS FULL TEST
********************************************************************************
マニュアル
・パフォーマンス・チューニング・ガイド10gリリース2（10.2）・リファレンス10g リリース2（10.2）
折りたたみ
展開