はじめに
Autonomous DatabaseのドキュメントにあるSQLトレースの取得方法ではイベント10046のようにバインド変数や待機イベントの情報は確認できません。そこでDBMS_USERDIAGパッケージを利用して、待機イベント、バインド変数も含めたSQLトレースの取得を実行してみます。DBMS_USERDIAGパッケージは23aiのドキュメントに記載があります。
今回は、SQL*PlusでADMINユーザーでSQLを実行しトレースを取得します。
1.クレデンシャルの準備
SQLトレースを出力するObject Storageにアクセスするための資格証明（クレデンシャル）を作成します。OCIユーザー名とOCI認証トークンを使用する場合はこちらのようなコマンドになります。
SQL*PlusでADMINユーザーで接続し、以下を実行します。
BEGIN
DBMS_CLOUD.CREATE_CREDENTIAL(
credential_name => 'クレデンシャル名',
username => '<OCIユーザー名>',
password => '<認証トークン>'
);
END;
/
今回はCRED_ADMINというクレデンシャルを作成しました。Object Storageのバケットにアクセスできるかどうかを以下で確認しておきます。
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にアクセスに利用する資格証明を設定します。
-- 設定値の確認
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を任意の文字列に設定します。
-- クライアントIDのセット
SQL> execute dbms_session.set_identifier('test');
PL/SQL procedure successfully completed.
SQLトレースの取得を開始します。DBMS_USERDIAGパッケージのENABLE_SQL_TRACE_EVENTプロシージャを利用すると引数でバインド変数や待機イベントの指定などの設定ができます。パラメータの詳細はドキュメントをご確認ください。
-- トレース取得開始.待機イベントの取得を指定（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> variable var_nation char(15) = 'JAPAN'
SQL> select count(*) from ssb.customer where c_nation = :var_nation;
COUNT(*)
----------
1200692
トレース取得を終了します。disbaleに1を指定します。
--トレース取得完了
execute dbms_userdiag.enable_sql_trace_event(disable=>1);
3.出力されたSQLトレースの確認
DEFAULT_LOGGING_BUCKETに指定したObject Storageのバケットを確認すると、sqltraceというフォルダがありその下に指定したクライアントID、さらにその下にトレースファイルが出力されています。
ダウンロードして内容を確認してみました。★でバインド変数の値が確認できます。
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環境)に持っていて整形しました。
$ tkprof sqltrace_test_sqlt_sqltrace_35465_31771.trc sqltrace_test_sqlt_sqltrace_35465_31771.txt
以下出力されたファイルの抜粋です。待機イベントが確認できます。
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チューニングにご利用いただけます。