Oracle DatabaseでSQLの性能計測1(SET AUTOTRACE TRACEONLY と SET TIMING ON編)【Oracle Database or GoldenGate Advent Calendar 2018 Day 1】

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

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

1日目はSQL*Plusの SET AUTOTRACE TRACEONLY と SET TIMING ON で、SQLの実行時間を計測してみるやで。彡(ﾟ)(ﾟ)

# 1. AUTOTRACE とは？

Oracle Databaseユーティリティ の SQL*Plus(sqlplus)の機能で、SQLの実行計画や実行統計の取得できます。

 > SQL*Plus ユーザーズ・ガイドおよびリファレンス 18c
 > 12.41.6 SET AUTOT[RACE] {ON | OFF | TRACE[ONLY]} [EXP[LAIN]] [STAT[ISTICS]]
 > https://docs.oracle.com/cd/E96517_01/sqpug/SET-system-variable-summary.html#GUID-0791433C-CA4A-4C79-BFF6-B7976E1534BA
 >  
 > 8.1 文のトレースについて
 > https://docs.oracle.com/cd/E96517_01/sqpug/tuning-SQL-Plus.html#GUID-1425180A-9917-429E-B908-B217C0CAC3DD


# 2. SET TIMING とは？

Oracle Databaseユーティリティ の SQL*Plus(sqlplus)の機能で、
SQL や PL/SQL を実行した際の経過時間を表示できます。  

 > SQL*Plus ユーザーズ・ガイドおよびリファレンス 18c
 > 12.41.64 SET TIMI[NG] {ON | OFF}
 > https://docs.oracle.com/cd/E96517_01/sqpug/SET-system-variable-summary.html#GUID-35276053-FA28-4CA3-94A8-8806682C9EA5

# 3. 実行サンプル

下記に実行サンプルを提示してみますやで彡(ﾟ)(ﾟ)

```sql
CONNECT AYSHIBAT/xxxxxxxx@yyyyyyyy

SET TIMING ON;           -- TIMING    を有効化しています。
SET AUTOTRACE TRACEONLY; -- AUTOTRACE を有効化しています。

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

Connected.

261 rows selected.

Elapsed: 00:00:05.22 ★SET TIMING ON によって出力されたSQLの経過時間です。

Execution Plan
----------------------------------------------------------
Plan hash value: 44130803

---------------------------------------------------------------------------------
| Id  | Operation           | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |           |     8 |   208 |    30   (7)| 00:00:01 |
|   1 |  SORT GROUP BY      |           |     8 |   208 |    30   (7)| 00:00:01 |
|*  2 |   HASH JOIN         |           |    26 |   676 |    29   (4)| 00:00:01 |
|   3 |    TABLE ACCESS FULL| ORDER_TBL |    26 |   286 |     3   (0)| 00:00:01 |
|*  4 |    TABLE ACCESS FULL| ITEM_TBL  |   300 |  4500 |    26   (4)| 00:00:01 |
---------------------------------------------------------------------------------

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

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

Statistics ★SET AUTOTRACE TRACEONLY によって出力されたSQLの実効統計
----------------------------------------------------------
         97  recursive calls
          0  db block gets
       9012  consistent gets
      15579  physical reads
          0  redo size
       7401  bytes sent via SQL*Net to client
        795  bytes received via SQL*Net from client
         19  SQL*Net roundtrips to/from client
         11  sorts (memory)
          0  sorts (disk)
        261  rows processed
```

# 4. 出力された統計の見方

SET TIMING ON の方はシンプル、経過時間そのものを確認します。

```sql
：
Elapsed: 00:00:05.22 ←コレを確認する。
：
```

SET AUTOTRACE TRACEONLY では様々な統計が出力されますが、
SQL性能観点だと「consistent gets」「physical reads」辺りをよく見ますかね彡(ﾟ)(ﾟ)  

```sql
：
Statistics
----------------------------------------------------------
         97  recursive calls
          0  db block gets
       9012  consistent gets ★SQLの読込ブロック数 ←これはよく見る
      15579  physical reads　★SQLのDisk IOブロック数 ←これはよく見る
          0  redo size
       7401  bytes sent via SQL*Net to client
        795  bytes received via SQL*Net from client
         19  SQL*Net roundtrips to/from client
         11  sorts (memory)
          0  sorts (disk)
        261  rows processed
：
```

 > 8.1.3 統計
 > https://docs.oracle.com/cd/E96517_01/sqpug/tuning-SQL-Plus.html#GUID-32806E04-0E05-4579-B2DB-E2C757CEA448
 > 統計は、文を実行したときにサーバーによって記録され、文の実行に必要とされた
 > システム・リソースを示します。結果には、次の統計が含まれます。
 > recursive calls
 > db block gets
 > ：

SQLチューニング観点で言えば、SET TIMING ON で確認できる「Elapsed」や
AUTOTRACEの「consistent gets」「physical reads」を血眼になって減らすんやね彡(ﾟ)(ﾟ)

# 5. AUTOTRACE TRACEONLY の注意点

まずひとつ目、AUTOTRACE TRACEONLY はその字面に反して
SQLのトランザクションが実行されてしまいます。下記記事参照彡(ﾟ)(ﾟ)

 > sqlplus の SET AUTOTRACE TRACEONLY は トレースオンリーじゃなくてトランザクションが実行されてしまう。
 > https://gonsuke777.hatenablog.com/entry/20160120/1453266062  

ふたつ目は、AUTOTRACE TRACEONLY で出てくる実行計画と
(共有プール上に格納された)実際の実行計画は異なるケースが有ります。下記記事参照

 > EXPLAIN PLAN FOR …(※AUTOTRACE TRACEONLY含む)で出てくる実行計画 と
 > SQL実行時の実行計画が異なるケースを作ってみる。
 > https://gonsuke777.hatenablog.com/entry/20150723/1437662167

これは下記マニュアルにも制限事項として記載が有ります。

 > 6.2.5 EXPLAIN PLANの制限事項
 > https://docs.oracle.com/cd/E96517_01/tgsql/generating-and-displaying-execution-plans.html#GUID-E2463C7B-F71A-4F06-85D3-1AF3D4D71CE8
 > Oracle Databaseでは、日付バインド変数の暗黙的な型変換を実行する文でのEXPLAIN PLANをサポートしません。
 > 一般にバインド変数では、EXPLAIN PLANが実際の実行計画を表していない場合があります。

過去あるいは後日記載する DBMS_XPLAN.DISPLAY_CURSOR や DBMS_SQLTUNE も併用や！彡(ﾟ)(ﾟ)

# 6. まとめ

上記のような制限事項が有るとはいえ、特に AUTOTRACE TRACEONLY は便利です。

sqlplus だけで操作が完結するんで、SQLチューニングの最盛期で
超高速PDCAを廻してるタイミングでは重宝しますやね彡(^)(^)