このエントリは 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ホーム・ディレクトリの下に配置されるファイルは、次のとおりです。
・トレース・ファイル - /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)
- で確認したディレクトリに移動して、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 ⇒ SQLNet message from client ⇒ SQLNet 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 による動的ビューからのトレース採取とか。
こちらはまたの機会に。彡(ﾟ)(ﾟ)