Oracle DatabaseでSQLの性能計測2(DBMS_XPLAN＆DBMS_SQLTUNE編)【Oracle Database or GoldenGate Advent Calendar 2018 Day 8】

このエントリは Oracle Database or GoldenGate Advent Calendar 2018 の Day 8 の記事となります。

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

今日は Oracle Database の DBMS_XPLANパッケージと DBMS_SQLTUNE で
SQLの実行時間を計測してみるやで彡(ﾟ)(ﾟ) Day 1 の続きになります。

Oracle DatabaseでSQLの性能計測1(SET AUTOTRACE TRACEONLY と SET TIMING ON編)
【Oracle Database or GoldenGate Advent Calendar 2018 Day 1】
https://gonsuke777.hatenablog.com/entry/2018/12/01/210651

1. DBMS_XPLANによるSQL実行時間の計測

1-1. DBMS_XPLAN とは？

Oracle Database の標準パッケージで、SQLの実行計画を出力する機能を持ちます。

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス 18c
210 DBMS_XPLAN
https://docs.oracle.com/cd/E96517_01/arpls/DBMS_XPLAN.html#GUID-BAD480AA-351A-48FE-A8E7-F0D8EF643EBF

DBMS_XPLANパッケージには幾つかの機能が有りますが、今回は DISPLAY_CURSORファンクションの
ALLSTATS書式による実行時の統計出力でSQLの実行時間を計測しますやで彡(ﾟ)(ﾟ)

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス 18c
210.4.4 DISPLAY_CURSORファンクション
https://docs.oracle.com/cd/E96517_01/arpls/DBMS_XPLAN.html#GUID-0EE333AF-E9AC-40A4-87D5-F6CF59D6C47B

1-2. ALLSTATS書式の前提条件

以下の「どちらか」の条件を満たして、SQLを実行する必要があります。

SQL に gather_plan_statisticsヒントを付与する。
STATISTICS_LEVELパラメータをALLにセットした状態でSQLを実行する。

更に以下の条件を満たす必要があります。

SQL の実行が終了していること(※Ctrl+Cによる強制終了でもOK)

1-3. DBMS_XPLAN.DISPLAY_CURSOR(ALLSTATS書式)の実行サンプル

下記が実行サンプルになります。STATISTICS_LEVELパラメータを
セッション単位（ALTER SESSION ～）で ALL にセットしています。

-- パラメータをセット
ALTER SESSION SET STATISTICS_LEVEL = ALL;

-- サンプル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;

-- DBMS_XPLAN.DISPLAY_CURSORによる実行計画の出力
SET LINESIZE 300;
SET PAGESIZE 1000;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('f9r2y6xdz6t84', NULL, 'ALL ALLSTATS LAST ADAPTIVE'));

実行結果は以下の通りです。

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('f9r2y6xdz6t84', NULL, 'ALL ALLSTATS LAST ADAPTIVE'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  f9r2y6xdz6t84, child number 0
-------------------------------------
An uncaught error happened in prepare_sql_statement : ORA-01403: no data found

Plan hash value: 44130803

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation           | Name      | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem | Used-Tmp|
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |           |      1 |        |       |    30 (100)|          |    261 |00:00:07.37 |    9068 |   4366 |   6795 |       |     |          |         |
|   1 |  SORT GROUP BY      |           |      1 |      8 |   208 |    30   (7)| 00:00:01 |    261 |00:00:07.37 |    9068 |   4366 |   6795 | 20480 | 20480 |18432  (0)|       |
|*  2 |   HASH JOIN         |           |      1 |     26 |   676 |    29   (4)| 00:00:01 |  26000 |00:00:07.20 |    9068 |   4366 |   6795 |   142M|  9292K| 17M (1)|   58368 |
|   3 |    TABLE ACCESS FULL| ORDER_TBL |      1 |     26 |   286 |     3   (0)| 00:00:01 |   2600K|00:00:00.60 |    8836 |      0 |      0 |       |     |          |         |
|*  4 |    TABLE ACCESS FULL| ITEM_TBL  |      1 |    300 |  4500 |    26   (4)| 00:00:01 |     10 |00:00:00.06 |      91 |      0 |      0 |       |     |          |         |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1
   3 - SEL$1 / A@SEL$1
   4 - SEL$1 / B@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("A"."ITEM_NO"="B"."ITEM_NO")
   4 - filter(TO_CHAR(INTERNAL_FUNCTION("B"."REGIST_DATE"),'YYYYMMDD')='20120801')

Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - (#keys=2) "B"."ITEM_NAME"[VARCHAR2,100], TRUNC(INTERNAL_FUNCTION("A"."ORDER_DATE"),'fmdd')[8], COUNT(*)[22]
   2 - (#keys=1) "A"."ORDER_DATE"[DATE,7], "B"."ITEM_NAME"[VARCHAR2,100]
   3 - (rowset=256) "A"."ITEM_NO"[NUMBER,22], "A"."ORDER_DATE"[DATE,7]
   4 - (rowset=256) "B"."ITEM_NO"[NUMBER,22], "B"."ITEM_NAME"[VARCHAR2,100]

1-4. 出力された統計の統計の見方(DBMS_XPLAN.DISPLAY_CURSORのALLSTATS書式)

まず A-Time を確認します。ここで実行計画の各ステップで
実際に掛かった実行時間を確認できます。今回の例では全体で7.37秒、
HASH JOINまでのステップで7.2秒ほど掛かっているのが確認できます。

：
Plan hash value: 44130803

-----------------------------------------…--------------…-
| Id  | Operation           | Name      |…|   A-Time   |…|
-----------------------------------------…--------------…-
|   0 | SELECT STATEMENT    |           |…|00:00:07.37 |…| ★全体で7.37秒程度時間が掛かっている。
|   1 |  SORT GROUP BY      |           |…|00:00:07.37 |…|
|*  2 |   HASH JOIN         |           |…|00:00:07.20 |…| ★HASH JOIN までのステップで7.2秒ほど掛かっている。
|   3 |    TABLE ACCESS FULL| ORDER_TBL |…|00:00:00.60 |…|
|*  4 |    TABLE ACCESS FULL| ITEM_TBL  |…|00:00:00.06 |…|
-----------------------------------------…--------------…-
：

次に E-Rows と A-Rows を確認します。E-Rows はオプティマイザの予測行数、
A-Rows は実測値として処理行数が確認できます。今回の例では STEP 3 の
ORDER_TBL表の予測と実測が大きく乖離していることが確認できます。

Plan hash value: 44130803

-----------------------------------------…----------…----------…-
| Id  | Operation           | Name      |…| E-Rows |…| A-Rows |…|
-----------------------------------------…----------…----------…-
|   0 | SELECT STATEMENT    |           |…|        |…|    261 |…|
|   1 |  SORT GROUP BY      |           |…|      8 |…|    261 |…|
|*  2 |   HASH JOIN         |           |…|     26 |…|  26000 |…|
|   3 |    TABLE ACCESS FULL| ORDER_TBL |…|     26 |…|   2600K|…| ★E-Rows(予測行数) と A-Rows(実測行数) が乖離している。
|*  4 |    TABLE ACCESS FULL| ITEM_TBL  |…|    300 |…|     10 |…|
-----------------------------------------…----------…----------…-

2. DBMS_SQLTUNEによるSQL実行時間の計測

2-1. DBMS_SQLTUNE とは？

Oracle Database のパッケージで、SQLチューニング関連の機能を持ちます。
Enterprise Edition の Tuning Packオプションの機能となります。

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス 18c
160 DBMS_SQLTUNE
https://docs.oracle.com/cd/E96517_01/arpls/DBMS_SQLTUNE.html#GUID-821462BF-1695-41CF-AFF7-FD23E9999C6A

Oracle Database ライセンス情報ユーザー・マニュアル 18c
1.6 機能、オプションおよびManagement Packの使用状況の確認
https://docs.oracle.com/cd/E96517_01/dblic/Licensing-Information.html#GUID-C3042D9A-5596-41A3-A08A-4581FED7634F
：
Oracle Tuning Pack
：
Oracle Tuning Packの機能は、データベース・サーバーAPIおよびコマンドライン・インタフェースでもアクセスできます。
：
・DBMS_SQLTUNE (注意事項を参照)

DBMS_SQLTUNEパッケージには幾つかの機能が有りますが、今回は REPORT_SQL_MONITORファンクションで
SQL監視(SQLモニタリング)のレポートを出力してみますやで彡(ﾟ)(ﾟ)

Oracle Database PL/SQLパッケージおよびタイプ・リファレンス 18c
160.5.27 REPORT_SQL_MONITORファンクション
https://docs.oracle.com/cd/E96517_01/arpls/DBMS_SQLTUNE.html#GUID-CFA1F851-1FC1-44D6-BB5C-76C3ADE1A483

2-2. DBMS_SQLTUNE.REPORT_SQL_MONITORファンクションの前提条件

以下の「どれか」の条件が満たされると、SQLの監視情報が自動でモニタリングされて、
REPORT_SQL_MONITORファンクションで確認可能となります。

SQL の実行時間が5秒以上
SQL がパラレル・クエリとして実行
SQL に MONITORヒントが付与

SQLが完了する必要は無く、実行中でも確認できます。

※(2018/12/16追記) SQLの実行計画のステップ数が300を超える場合は、
上記の条件を満たしていてもSQL監視の対象になりません。
隠しパラメータ"_sqlmon_max_planlines"を300よりも多くセットする必要があります。

-- データベース全体でセットする場合
ALTER SYSTEM SET "_sqlmon_max_planlines"=1000 SCOPE=BOTH SID='*';

-- セッション単位でセットする場合
ALTER SESSION SET "_sqlmon_max_planlines"=1000;

上記パラメータの詳細は下記ドキュメントをご参照下さい(｀･ω･)ゞ ※要My Oracle Supportアカウント

How to Monitor SQL Statements with Large Plans Using Real-Time SQL Monitoring? (ドキュメントID 1613163.1)
https://support.oracle.com/epmos/faces/DocumentDisplay?id=1613163.1

2-3. DBMS_SQLTUNE.REPORT_SQL_MONITORの実行サンプル

下記が実行サンプルになります。MONITORヒントを付与してSQLを実行しています。

ALTER SESSION SET STATISTICS_LEVEL = ALL;

-- サンプル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;

-- DBMS_SQLTUNE.REPORT_SQL_MONITORによるレポート出力
SET LONG 1000000
SET LONGC 1000000
SET LINESIZE 300;
SET PAGESIZE 1000;
VAR c_rep CLOB;
EXEC :c_rep := DBMS_SQLTUNE.REPORT_SQL_MONITOR(sql_id => 'f9r2y6xdz6t84', TYPE => 'TEXT');
PRINT c_rep;

実行結果は以下の通りです。

SQL> EXEC :c_rep := DBMS_SQLTUNE.REPORT_SQL_MONITOR(sql_id => 'f9r2y6xdz6t84', TYPE => 'TEXT');

PL/SQL procedure successfully completed.

SQL> PRINT c_rep;

C_REP
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report

SQL Text
------------------------------
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

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  AYSHIBAT (88:40832)
 SQL ID              :  f9r2y6xdz6t84
 SQL Execution ID    :  16777216
 Execution Started   :  12/08/2018 04:07:45
 First Refresh Time  :  12/08/2018 04:07:45
 Last Refresh Time   :  12/08/2018 04:07:53
 Duration            :  8s
 Module/Action       :  SQL*Plus/-
 Service             :  orcl
 Program             :  sqlplus@localhost.localdomain (TNS V1-V3)
 Fetch Calls         :  19

Global Stats
===========================================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes |
===========================================================================================
|    7.37 |    1.31 |     5.56 |     0.51 |    19 |   9068 |  292 |  34MB |   453 |  53MB |
===========================================================================================

SQL Plan Monitoring Details (Plan Hash Value=44130803)
==========================================================================================================================================================================================
| Id |       Operation       |   Name    |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp  | Activity |    Activity Detail       |
|    |                       |           | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes | (Max) | (Max) |   (%)    |      (# samples)         |
==========================================================================================================================================================================================
|  0 | SELECT STATEMENT      |           |         |      |         1 |     +8 |     1 |      261 |      |       |       |       |     . |     . |    12.50 | local write wait (1)     |
|  1 |   SORT GROUP BY       |           |       8 |   30 |         1 |     +8 |     1 |      261 |      |       |       |       | 18432 |     . |        |                            |
|  2 |    HASH JOIN          |           |      26 |   29 |         7 |     +2 |     1 |    26000 |  291 |  34MB |   453 |  53MB |  18MB |  57MB |    75.00 | direct path write temp (6) |
|  3 |     TABLE ACCESS FULL | ORDER_TBL |      26 |    3 |         5 |     +2 |     1 |       3M |      |       |       |       |     . |     . |        |                            |
|  4 |     TABLE ACCESS FULL | ITEM_TBL  |     300 |   26 |         1 |     +8 |     1 |       10 |      |       |       |       |     . |     . |        |                            |
==========================================================================================================================================================================================

2-4. 出力された統計の統計の見方(DBMS_SQLTUNE.REPORT_SQL_MONITORによるレポート出力)

まず Global Information の Duration を確認します。SQL全体の実行時間を確認できます。

Global Information
------------------------------
：
 Duration            :  8s
：

今回のSQLでは該当しませんが、Global Stats の Elapsed Time(s) は
パラレル・クエリの子プロセス(スレーブ)のSQL実行時間も積算されるため、
その点を考慮して確認する必要があります。

：
Global Stats
===========================================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes |
===========================================================================================
|    7.37 |    1.31 |     5.56 |     0.51 |    19 |   9068 |  292 |  34MB |   453 |  53MB |
===========================================================================================
^^^^^^^^^^^子プロセス(スレーブ)のSQL実行時間も含んだ積算値
：

次に Activity(%) と Activity Detail(# samples) を確認します。
実行計画のどこで時間が掛かっているか、どんな待機イベントで時間が掛かっているかを
直感的に把握できるため、非常に有用な情報となります。

SQL Plan Monitoring Details (Plan Hash Value=44130803)
==========================================…=========================================
| Id |       Operation       |   Name    |…| Activity |    Activity Detail       |
|    |                       |           |…|   (%)    |      (# samples)         |
==========================================…=========================================
|  0 | SELECT STATEMENT      |           |…|    12.50 | local write wait (1)     |
|  1 |   SORT GROUP BY       |           |…|        |                            |
|  2 |    HASH JOIN          |           |…|    75.00 | direct path write temp (6) | ★direct path write temp で全体の75%を占める。
|  3 |     TABLE ACCESS FULL | ORDER_TBL |…|        |                            |
|  4 |     TABLE ACCESS FULL | ITEM_TBL  |…|        |                            |
==========================================…=========================================

あとはDBMS_XPLANと同様にRows(Estim)の予測値とRows(Actual)の実測値を確認します。

SQL Plan Monitoring Details (Plan Hash Value=44130803)
====================================================…============…=
| Id |       Operation       |   Name    |  Rows   |…|   Rows   |…|
|    |                       |           | (Estim) |…| (Actual) |…|
====================================================…============…=
|  0 | SELECT STATEMENT      |           |         |…|      261 |…|
|  1 |   SORT GROUP BY       |           |       8 |…|      261 |…|
|  2 |    HASH JOIN          |           |      26 |…|    26000 |…|
|  3 |     TABLE ACCESS FULL | ORDER_TBL |      26 |…|       3M |…| ★ 26件(予測)と3M件(実測)で大きく乖離
|  4 |     TABLE ACCESS FULL | ITEM_TBL  |     300 |…|       10 |…|
====================================================…============…=

3. 今回のケースでのSQL性能改善(チューニング)

このエントリは SQL性能計測をメインとしているため
チューニングの詳細は割愛しますが、今回のケースでは

ORDER_TBL表の E-Rows(予測値) と A-Rows(実測値)が乖離している。
HASH JOINのステップで時間が掛かっている。

事が、DBMS_XPLAN と DBMS_SQLTUNE の性能計測により確認できます。
このようなケースでは以下のようなチューニングを試すのがセオリーとなります。

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

どのチューニングも E-Rows(予測値) と A-Rows(実測値) の
乖離を埋めて、良い実行計画が生成される事を期待する手法となります。

4. まとめ

DBMS_XPLAN.DISPLAY_CURSOR と DBMS_SQLTUNE.REPORT_SQL_MONITOR による性能計測は、
SQLのボトルネック特定に非常に有効な手段となります。皆活用するんやで彡(^)(^)

もっと詳しく説明した資料も有るので、皆読んでクレメンス(ステマ

Oracle DBA & Developer Day 2013
https://www.oracle.com/technetwork/jp/ondemand/ddd-2013-2051348-ja.html

【A-1】オラクル・コンサルが語る！ SQLチューニングに必要な考え方と最新テクニック
http://www.oracle.com/webfolder/technetwork/jp/ondemand/ddd2013/A-1.pdf