[Autonomous Database] 待機イベント、バインド変数を含めたSQLトレースを取得してみる

# はじめに
Autonomous DatabaseのドキュメントにあるSQLトレースの取得方法ではイベント10046のようにバインド変数や待機イベントの情報は確認できません。そこでDBMS_USERDIAGパッケージを利用して、待機イベント、バインド変数も含めたSQLトレースの取得を実行してみます。DBMS_USERDIAGパッケージは[23aiのドキュメント](https://docs.oracle.com/cd/F82042_01/arpls/dbms_userdiag1.html)に記載があります。

今回は、SQL*PlusでADMINユーザーでSQLを実行しトレースを取得します。


# 1.クレデンシャルの準備
SQLトレースを出力するObject Storageにアクセスするための資格証明（クレデンシャル）を作成します。OCIユーザー名とOCI認証トークンを使用する場合はこちらのようなコマンドになります。
SQL*PlusでADMINユーザーで接続し、以下を実行します。

```sql
BEGIN
  DBMS_CLOUD.CREATE_CREDENTIAL(
     credential_name => 'クレデンシャル名',
     username => '<OCIユーザー名>', 
     password => '<認証トークン>'
);
END;
/	
```
今回はCRED_ADMINというクレデンシャルを作成しました。Object Storageのバケットにアクセスできるかどうかを以下で確認しておきます。

```sql
SELECT * FROM DBMS_CLOUD.LIST_OBJECTS('CRED_ADMIN', 'https://objectstorage.ap-tokyo-1.oraclecloud.com/n/<テナンシー名>/b/<バケット名>/o/');
```

# 2. 初期化パラメータの設定（Object StorageのバケットのURLとアクセスに利用する資格証明）
**DEFAULT_LOGGING_BUCKET**にトレースを出力するバケットのURL,**DEFAULT_CREDENTIAL**にアクセスに利用する資格証明を設定します。

```sql
--　設定値の確認
set pages 100
SQL> select * from database_properties where property_name in ('DEFAULT_LOGGING_BUCKET','DEFAULT_CREDENTIAL');

no rows selected

-- DEFAULT_LOGGING_BUCKETの設定
ALTER DATABASE PROPERTY SET 
   DEFAULT_LOGGING_BUCKET = 'https://objectstorage.ap-tokyo-1.oraclecloud.com/n/<テナンシー名>/b/<バケット名>/o/';

-- DEFAULT_CREDENTIALの設定
ALTER DATABASE PROPERTY SET  DEFAULT_CREDENTIAL = 'ADMIN.CRED_ADMIN';

--　再度確認
select * from database_properties where property_name in ('DEFAULT_LOGGING_BUCKET','DEFAULT_CREDENTIAL');

PROPERTY_NAME
--------------------------------------------------------------------------------
PROPERTY_VALUE
--------------------------------------------------------------------------------
DESCRIPTION
--------------------------------------------------------------------------------
DEFAULT_LOGGING_BUCKET
https://objectstorage.ap-tokyo-1.oraclecloud.com/n/<テナンシー名>/b/<バケット名>/o/
Default logging bucket name

DEFAULT_CREDENTIAL
ADMIN.CRED_ADMIN
Default credential object name
```

# 3. SQLトレースの取得とSQLの実行
出力したトレースをわかりやすくするため、DBMS_SESSIONパッケージのSET_IDENTIFIERプロシージャでクライアントIDを任意の文字列に設定します。

```sql
-- クライアントIDのセット
SQL> execute  dbms_session.set_identifier('test');

PL/SQL procedure successfully completed.
```

SQLトレースの取得を開始します。DBMS_USERDIAGパッケージのENABLE_SQL_TRACE_EVENTプロシージャを利用すると引数でバインド変数や待機イベントの指定などの設定ができます。パラメータの詳細は[ドキュメント](https://docs.oracle.com/cd/F82042_01/arpls/dbms_userdiag1.html#GUID-46A5D5BA-8A50-4829-A630-1457F71D72E2)をご確認ください。

```sql
-- トレース取得開始.待機イベントの取得を指定（event 10046のレベル4とレベル8⇒つまりレベル12, level=>12で指定しても同じはず)
SQL> execute dbms_userdiag.enable_sql_trace_event(binds=>1,waits=>1);

PL/SQL procedure successfully completed.
```

続けてトレースを取得するSQLを実行します。サンプル表として提供されているSSB.CUSTOMERの表をバインド変数に指定した条件で取得します。

```sql
-- SQLの実行
SQL> variable var_nation char(15) = 'JAPAN'

SQL> select count(*) from ssb.customer where c_nation = :var_nation;

  COUNT(*)
----------
   1200692
```

トレース取得を終了します。disbaleに1を指定します。

```sql
--トレース取得完了
execute dbms_userdiag.enable_sql_trace_event(disable=>1);
```

# 3.出力されたSQLトレースの確認
DEFAULT_LOGGING_BUCKETに指定したObject Storageのバケットを確認すると、sqltraceというフォルダがありその下に指定したクライアントID、さらにその下にトレースファイルが出力されています。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/134317/a221ba55-df07-47e3-9b98-5942ff789fac.png)


ダウンロードして内容を確認してみました。★でバインド変数の値が確認できます。

```
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.27.0.1.0Build label:    RDBMS_PT.DBCLOUD19_LINUX.X64_250304ORACLE_HOME:    /u02/app/oracle/product/19.0.0.0/dbhome_1
:
=====================
PARSING IN CURSOR #139880270460016 len=63 dep=0 uid=92 oct=3 lid=92 tim=15579696880583 hv=2052763323 ad='19c0e42238' sqlid='c6924htx5pbpv'
 select count(*) from ssb.customer where c_nation = :var_nation
END OF STMT
PARSE #139880270460016:c=420,e=420,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=15579696880582
WAIT #139880270460016: nam='Disk file operations I/O' ela= 491 FileOperation=2 fileno=5722 filetype=2 obj#=-1 tim=15579696881243
=====================
:
BINDS #139880270460016:

 Bind#0
  oacdty=96 mxl=128(45) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=873 siz=128 off=0
  kxsbbbfp=7f3869d59e78  bln=128  avl=05  flg=05
  value="JAPAN" ★
:
```

# 4.tkprofで整形する
tkprofはOracle Databaseのユーティリティですが、OSにログインできないAutonomous Databaseでは利用できません。別の環境(今回は23aiのBaseDB環境)に持っていて整形しました。

```sql
$ tkprof sqltrace_test_sqlt_sqltrace_35465_31771.trc sqltrace_test_sqlt_sqltrace_35465_31771.txt
```
以下出力されたファイルの抜粋です。待機イベントが確認できます。

```sql
SQL ID: 7a58pdhtgdypv Plan Hash: 882626266

select count(*)
from
 ssb.customer where c_nation = :var_nation


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        1      0.04       0.06      95591      95593          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.05       0.06      95591      95593          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=95593 pr=95591 pw=0 time=61792 us starts=1 direct read=0 direct write=0)
       751        751        751   TABLE ACCESS STORAGE FULL CUSTOMER (cr=95593 pr=95591 pw=0 time=51320 us starts=1 direct read=0 direct write=0 cost=26466 size=19200000 card=1200000)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  cell disk open                                 94        0.00          0.01
  cell single block physical read: xrmem cache
                                                  1        0.00          0.00
  cell smart table scan                         102        0.00          0.00
  PGA memory operation                            1        0.00          0.00
  SQL*Net message from client                     1        7.59          7.59
********************************************************************************
```

# おわりに
Autonomous Databaseｄバインド変数、待機イベントを含めたSQLトレースを取得してみました。既存のOracle Database同様に情報が取得できますので、アプリケーションのSQLチューニングにご利用いただけます。