1. SQLトレースとは？
2. SQLトレースの出力先と出力可能サイズの確認
3. DBMS_SESSIONパッケージでセッション単位でSQLトレースを取得
4. 出力されたSQLトレースの確認と整形(tkprof)
5. 整形(tkprof)済みトレースの見方
6. 整形(tkprof)前の生トレース確認
7. まとめ

このエントリは Oracle Database or GoldenGate Advent Calendar 2018 の Day 20 の
記事となります。一日遅れてしまいました。スミマセン彡(-)(-)

Oracle Database or GoldenGate Advent Calendar 2018
https://adventar.org/calendars/3525

今日は Oracle Database で SQLトレースを取得して、
SQLの実行時間を計測してみるやで彡(ﾟ)(ﾟ) Day 8 の続きになります。

Oracle DatabaseでSQLの性能計測2(DBMS_XPLAN＆DBMS_SQLTUNE編)
【Oracle Database or GoldenGate Advent Calendar 2018 Day 8】
https://gonsuke777.hatenablog.com/entry/2018/12/08/215428

1. SQLトレースとは？

セッション内で実行される個々のSQLのパフォーマンス情報を取得する機能です。
この記事でも幾つか記述しますが、下記のような情報を採取する事が可能です。

Oracle Database SQLチューニング・ガイド 18c
23.1.3.1 SQLトレース機能の概要
https://docs.oracle.com/cd/E96517_01/tgsql/performing-application-tracing.html#GUID-374ABE48-C63F-4A7B-B80E-906A51F9246C
SQLトレースは、文ごとに次の統計を生成します。
・解析、実行、フェッチのカウント
・CPU時間および経過時間
・物理読取りおよび論理読取り
・処理された行数
：

2. SQLトレースの出力先と出力可能サイズの確認

下記マニュアルの手順通り、まずSQLトレースの出力先と出力可能サイズを確認します。

Oracle Database SQLチューニング・ガイド 18c
23.4.1 手順1: トレース・ファイル管理用の初期化パラメータの設定
https://docs.oracle.com/cd/E96517_01/tgsql/performing-application-tracing.html#GUID-A4FD1913-D35A-4EE6-9CE8-361718433E91

まず DIAGNOSTIC_DESTパラメータのパスを確認します。

SHOW PARAMETER DIAG

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
diagnostic_dest                      string      /u01/app/oracle

上記の結果より、自動診断リポジトリ(ADR)ホームの場所を確定します。

Oracle Database データベース・リファレンス 18c
1.100 DIAGNOSTIC_DEST
https://docs.oracle.com/cd/E96517_01/refrn/DIAGNOSTIC_DEST.html#GUID-BFE9648A-24D4-4717-8C33-21B0868401EE
:
DIAGNOSTIC_DESTによって指定されるディレクトリの構造は、次のとおりです。

<diagnostic_dest>/diag/rdbms/<dbname>/<instname>
:

ADRホーム・ディレクトリの下に配置されるファイルは、次のとおりです。

・トレース・ファイル - <adr-home>/traceサブディレクトリに配置されます。
:

今回の環境は Single(非RAC)環境で DB名, インスタンス名, いずれも orclcdb となります。
トレースファイルは ADRホームのtrace配下に出力されるため、今回は下記のパスに出力されます。

# トレースファイルの出力先
/u01/app/oracle/diag/rdbms/orclcdb/orclcdb/trace

MAX_DUMP_FILE_SIZEパラメータも確認します。今回の環境は unlmited にセットされています。

SHOW PARAMETER MAX_DUMP

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_dump_file_size                   string      unlimited

3. DBMS_SESSIONパッケージでセッション単位でSQLトレースを取得

SQLトレースを取得するには幾つかの方法が有りますが、
今回は DBMS_SESSIONパッケージのSESSION_TRACE_ENABLEプロシージャで、
セッション単位でSQLトレースを取得します。10046？知らんなぁ？彡(ﾟ)(ﾟ)

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス 18c
146 DBMS_SESSION
SESSION_TRACE_ENABLEプロシージャ
https://docs.oracle.com/cd/E96517_01/arpls/DBMS_SESSION.html#GUID-0EF8429F-B552-40D0-885C-3C560A66152D

トレースファイルを識別し易くするために、TRACEFILE_IDENTIFIERパラメータもセットします。

Oracle Databaseデータベース・リファレンス, 18c
1.336 TRACEFILE_IDENTIFIER
https://docs.oracle.com/cd/E96517_01/refrn/TRACEFILE_IDENTIFIER.html#GUID-976352B6-1189-4B73-835B-9D5441D11115

下記がSQLトレース取得の実行サンプルになります。TRACEFILE_IDENTIFIERパラメータを
セットしつつ、待機イベント／バインド変数／行ソース統計を全て取得します。

それぞれのパラメータ(waits, binds, plan_stat)の意味は、生トレースの章で解説します。

-- TRACEFILE_IDENTIFIERパラメータをセット
ALTER SESSION SET TRACEFILE_IDENTIFIER = "AYSHIBAT";

-- SQLトレースを有効化
EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(waits => TRUE, binds => TRUE, plan_stat => 'ALL_EXECUTIONS');

-- サンプルSQL
SELECT /*+ MONITOR */
       B.ITEM_NAME
     , TRUNC(A.ORDER_DATE, 'DD') AS ORDER_DAILY
     , COUNT(*)
  FROM ORDER_TBL A
     , ITEM_TBL B
 WHERE A.ITEM_NO  = B.ITEM_NO
--   AND B.ITEM_NO BETWEEN 1 AND 100
   AND TO_CHAR(B.REGIST_DATE, 'YYYYMMDD') = '20120801'
 GROUP BY B.ITEM_NAME, TRUNC(A.ORDER_DATE, 'DD')
 ORDER BY 1;

-- SQLトレースを無効化
EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;

Session altered.

PL/SQL procedure successfully completed.

261 rows selected.

PL/SQL procedure successfully completed.

4. 出力されたSQLトレースの確認と整形(tkprof)

2.で確認したディレクトリに移動して、SQLトレースファイルを確認します。

cd /u01/app/oracle/diag/rdbms/orclcdb/orclcdb/trace
ls -ltra *AYSHIBAT*

[oracle@localhost trace]$
[oracle@localhost trace]$ cd /u01/app/oracle/diag/rdbms/orclcdb/orclcdb/trace
[oracle@localhost trace]$ ls -ltra *AYSHIBAT*
-rw-r-----. 1 oracle oinstall  123298 Dec 21 01:03 orclcdb_ora_26747_AYSHIBAT.trm
-rw-r-----. 1 oracle oinstall 1842101 Dec 21 01:03 orclcdb_ora_26747_AYSHIBAT.trc ★出力されたトレース
[oracle@localhost trace]$

出力されたトレースファイルをtkprofコマンドで整形します。
tkprofにも幾つかオプション(sys=no, aggregate=no, sortなど)が有るのですが、
今回はシンプルに出力ファイル名のみ指定しますやで彡(ﾟ)(ﾟ)

tkprof orclcdb_ora_26747_AYSHIBAT.trc orclcdb_ora_26747_AYSHIBAT.trc.txt
ls -ltra *AYSHIBAT*

TKPROF: Release 18.0.0.0.0 - Development on Fri Dec 21 01:29:27 2018

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

-rw-r-----. 1 oracle oinstall  123298 Dec 21 01:03 orclcdb_ora_26747_AYSHIBAT.trm
-rw-r-----. 1 oracle oinstall 1842101 Dec 21 01:03 orclcdb_ora_26747_AYSHIBAT.trc
-rw-r--r--. 1 oracle oinstall   41833 Dec 21 01:29 orclcdb_ora_26747_AYSHIBAT.trc.txt ★整形されたトレース

5. 整形(tkprof)済みトレースの見方

5-1. 整形(tkprof)済みトレースの抜粋

整形(tkprof)済みトレースから、対象SQLの結果を抜粋します。

********************************************************************************
:
SELECT /*+ MONITOR */
       B.ITEM_NAME
     , TRUNC(A.ORDER_DATE, 'DD') AS ORDER_DAILY
     , COUNT(*)
  FROM ORDER_TBL A
     , ITEM_TBL B
 WHERE A.ITEM_NO  = B.ITEM_NO
--   AND B.ITEM_NO BETWEEN 1 AND 100
   AND TO_CHAR(B.REGIST_DATE, 'YYYYMMDD') = '20120801'
 GROUP BY B.ITEM_NAME, TRUNC(A.ORDER_DATE, 'DD')
 ORDER BY 1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       19      3.21      13.70       6669       8926          0         261
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      3.23      13.73       6669       8926          0         261

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 129
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       261        261        261  SORT GROUP BY (cr=8926 pr=6669 pw=6669 time=13704807 us starts=1 cost=30 size=208 card=8)
     26000      26000      26000   HASH JOIN  (cr=8926 pr=6669 pw=6669 time=13880000 us starts=1 cost=29 size=676 card=26)
   2600000    2600000    2600000    TABLE ACCESS FULL ORDER_TBL (cr=8835 pr=0 pw=0 time=378587 us starts=1 cost=3 size=286 card=26)
        10         10         10    TABLE ACCESS FULL ITEM_TBL (cr=91 pr=0 pw=0 time=856 us starts=1 cost=26 size=4500 card=300)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      19        0.00          0.00
  direct path write temp                       6669        0.00         11.31
  direct path read temp                        6669        0.00          0.06
  SQL*Net message from client                    19        3.38          3.48
********************************************************************************
:

5-2. 整形(tkprof)済みトレースの表形式統計の確認

下記の部分(表形式の統計)に着目します。

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       19      3.21      13.70       6669       8926          0         261
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21    ★3.23     ★13.73     ★6669     ★8926          0       ★261

対象のSQLについて、cpu時間で3.23秒、経過時間が13.73秒、diskアクセスが6669回、
一貫性読取で8926ブロック、フェッチ行数は261行であることが確認できます。

それぞれの統計の意味はマニュアルも参照して下さい。

Oracle Database SQLチューニング・ガイド 18c
23.6.2.5.2 TKPROFの表形式の統計
https://docs.oracle.com/cd/E96517_01/tgsql/performing-application-tracing.html#GUID-B6EE4109-5946-415D-9B75-EC1B73D16B87

整形(tkprof)済みSQLトレースの冒頭にも載ってますやね！彡(ﾟ)(ﾟ)

:
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************
:

5-3. 整形(tkprof)済みトレースの行ソース統計の確認

次は下記の部分(行ソース統計)に着目します。

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       261        261        261  SORT GROUP BY (cr=8926 pr=6669 pw=6669 time=13704807 us starts=1 cost=30 size=208 card=8)
     26000      26000      26000   HASH JOIN  (cr=8926 pr=6669 pw=6669 time=13880000 us starts=1 cost=29 size=676 card=26)
   2600000    2600000    2600000    TABLE ACCESS FULL ORDER_TBL (cr=8835 pr=0 pw=0 time=378587 us starts=1 cost=3 size=286 card=26)
        10         10         10    TABLE ACCESS FULL ITEM_TBL (cr=91 pr=0 pw=0 time=856 us starts=1 cost=26 size=4500 card=300)

まずは time値に着目します。実行計画の各ステップで、
どの程度時間が掛かったかを表します。μ秒(1/1,000,000秒)表記です。

Row Source Operation
---------------------------------------------------
SORT GROUP BY                 time=13704807 us ★ここまでで13.70秒掛かっている。
 HASH JOIN                    time=13880000 us ★ここまでで13.88秒掛かっている。
  TABLE ACCESS FULL ORDER_TBL time=378587 us
  TABLE ACCESS FULL ITEM_TBL  time=856 us

上記例だと HASH JOIN までのステップで 13880000us(13.88秒)、
SORT GROUP BY までのステップで 13704807us(約13.7秒)掛かっています。
※矛盾が有りますが、傾向を掴む事が重要なので多少の誤差は(ﾟεﾟ )ｷﾆｼﾅｲ!

次に cr値、pr値、pw値に着目。cr値は一貫性読込のブロック数、
pr値は物理読込の回数、pw値は物理書込の回数を表します。

Row Source Operation
---------------------------------------------------
SORT GROUP BY                 cr=8926 pr=6669 pw=6669 
 HASH JOIN                    cr=8926 pr=6669 pw=6669 ★ここで6669回の物理読込／物理書込が発生
  TABLE ACCESS FULL ORDER_TBL cr=8835 pr=0    pw=0    ★ここまでで8835ブロックの一貫性読込が発生
  TABLE ACCESS FULL ITEM_TBL  cr=91   pr=0    pw=0

上記例だと TABLE ACCESS FULL ORDER_TBL のステップで 8835ブロックの一貫性読込が、
HASH JOIN のステップで 6669回の物理読込／物理書込が発生している事が確認できます。

その次はオプティマイザの予測値と実測値の確認。
cost がオプティマイザの予測コスト値、size が予測バイト数、card が予測行数になりますが、
その中の予測行数(card)と実測行数(Rows)を比較します。
DBMS_XPLAN や DBMS_SQLTUNE の時と同じ流れですやね彡(ﾟ)(ﾟ)

Rows (1st) Row Source Operation
---------- ---------------------------------------------------
       261 SORT GROUP BY                 card=8
     26000  HASH JOIN                    card=26
   2600000   TABLE ACCESS FULL ORDER_TBL card=26 ★実測値(2,600,000行)と予測値(26行)が乖離
        10   TABLE ACCESS FULL ITEM_TBL  card=300

上記例だと ORDER_TBL の実測行数(2,600,000行)と予測行数(26行)が乖離しているのが確認できます。

各行ソース統計の値の意味については、マニュアルも参照して下さい。

Oracle Database SQLチューニング・ガイド 18c
23.6.2.5.4 TKPROFの行ソースの操作
https://docs.oracle.com/cd/E96517_01/tgsql/performing-application-tracing.html#GUID-77906451-193D-4D73-BA49-95A64445C673

下記のドキュメントも確認ですやで彡(ﾟ)(ﾟ) ※要My Oracle Supportアカウント

TKProf Interpretation (9i and above) (ドキュメントID 760786.1)
https://support.oracle.com/epmos/faces/DocumentDisplay?id=760786.1

5-4. 整形(tkprof)済みトレースの待機イベントの確認

最後に下記の部分(待機イベント部分)に着目します。

Elapsed times include waiting on following events:
  Event waited on                   Times   Max. Wait  Total Waited
  ------------------------------   Waited  ----------  ------------
  SQL*Net message to client            19        0.00          0.00
  direct path write temp             6669        0.00         11.31 ★direct path write tempで時間が掛かっている。
  direct path read temp              6669        0.00          0.06
  SQL*Net message from client          19        3.38          3.48

以上の結果より、下記の事実が確認できます。

ORDER_TBL表の Rows(実測値) と card(予測値)が乖離している。
HASH JOINのステップで時間が掛かっている。
direct path write tempの待機イベントで時間が掛かっている。

このようなケースでは以下のようなチューニングを試すのがセオリーとなります。※前回のコピペ

オプティマイザ統計の採取
ヒストグラム、拡張統計(複数列統計, 式統計)の取得
SQLチューニング・アドバイザの実行と SQLプロファイルの適用(※)
　※SQLプロファイルが提案された場合

6. 整形(tkprof)前の生トレース確認

6-1. 整形(tkprof)前の生トレースで確認できる情報

整形前の生トレースを見ると、下記の情報も確認できます。

待機イベントの(WAIT行)
バインド変数(BINDSセクション)
行ソース統計(STAT行)
etc...

下記に生トレースに関する先端技様の良い記事もあります。是非ご参照を彡(^)(^)

整形する前の SQL トレースを見ることが有益なケース
http://www.intellilink.co.jp/article/column/ora-report20150507.html

6-2. WAIT行(待機イベント)を生トレースで確認

DBMS_SESSION.SESSION_TRACE_ENABLE の waits => TRUE は、
SQLトレースにWAIT行を出力するオプションとなります。

下記は生トレースのWAIT行サンプルです。

-- 生トレースのWAIT行サンプル
：
WAIT #140512706274008: nam='SQL*Net message to client' ela= 11 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14331548081
WAIT #140512706274008: nam='direct path write temp' ela= 4310 file number=203 first dba=391 block cnt=1 obj#=-1 tim=14331638606
WAIT #140512706274008: nam='direct path write temp' ela= 1176 file number=203 first dba=392 block cnt=1 obj#=-1 tim=14331640040
WAIT #140512706274008: nam='direct path write temp' ela= 844 file number=203 first dba=393 block cnt=1 obj#=-1 tim=14331641358
：
FETCH #140512706274008:c=158,e=157,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=44130803,tim=14345356617
WAIT #140512706274008: nam='SQL*Net message from client' ela= 3721 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14345360474
WAIT #140512706274008: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14345360605
FETCH #140512706274008:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=44130803,tim=14345360673
WAIT #140512706274008: nam='SQL*Net message from client' ela= 4547 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14345365303
WAIT #140512706274008: nam='SQL*Net message to client' ela= 286 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14345365981
FETCH #140512706274008:c=635,e=633,p=0,cr=0,cu=0,mis=0,r=5,dep=0,og=1,plh=44130803,tim=14345366311
：

FETCH ⇒ SQL*Net message from client ⇒ SQL*Net message to client の流れが確認できますね～彡(ﾟ)(ﾟ)

6-3. BINDSセクション(バインド変数)を生トレースで確認

DBMS_SESSION.SESSION_TRACE_ENABLE の binds => TRUE は、
SQLトレースにBINDSセクションを出力するオプションとなります。

下記は生トレースのBINDSサンプルです。

-- 生トレースのBINDSサンプル
:
BINDS #140512706270952:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=7fcba3a6d150  bln=22  avl=03  flg=05
  value=715
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=7fcba3a6d168  bln=22  avl=02  flg=01
  value=5
:

バインド変数の取得＆参照は完全な代替機能が無く、
生トレースの中では最もよく参照される箇所ではないでしょうか彡(ﾟ)(ﾟ)

6-4. STAT行(行ソース統計)を生トレースで確認

DBMS_SESSION.SESSION_TRACE_ENABLE の plan_stat => 'ALL_EXECUTIONS' は、
SQLトレースにSTAT行(行ソース統計)の出力を毎回強制するオプションとなります。

下記は生トレースのSTAT行サンプルです。

：
STAT #140512706274008 id=1 cnt=261 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=8926 pr=6669 pw=6669 str=1 time=13704807 us cost=30 size=208 card=8)'
STAT #140512706274008 id=2 cnt=26000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=8926 pr=6669 pw=6669 str=1 time=13880000 us cost=29 size=676 card=26)'
STAT #140512706274008 id=3 cnt=2600000 pid=2 pos=1 obj=79972 op='TABLE ACCESS FULL ORDER_TBL (cr=8835 pr=0 pw=0 str=1 time=378587 us cost=3 size=286 card=26)'
STAT #140512706274008 id=4 cnt=10 pid=2 pos=2 obj=79975 op='TABLE ACCESS FULL ITEM_TBL (cr=91 pr=0 pw=0 str=1 time=856 us cost=26 size=4500 card=300)'
：

デフォルト値ではSQLの初回実行のみSTAT行(行ソース統計)が出力されますが、
plan_stat => 'ALL_EXECUTIONS' で毎回出力できるようにするんですやね彡(ﾟ)(ﾟ)

7. まとめ

Standard Edition な環境でも、SQLトレースで闘える！彡(^)(^)
でも Tuning Pack(DBMS_SQLTUNE) は便利なんで、こちらもよろしくです。

SQLトレースはまだまだネタが多いですやね。TRCSESSユーティリティとか、
V$DIAG_TRACE_FILE や V$DIAG_TRACE_FILE_CONTENTS による動的ビューからのトレース採取とか。

こちらはまたの機会に。彡(ﾟ)(ﾟ)

ねら～ITエンジニア雑記

やきうのお兄ちゃんが綴るOracle Databaseメインのブログ

Oracle DatabaseでSQLの性能計測3(SQLトレース編)【Oracle Database or GoldenGate Advent Calendar 2018 Day 20】