EVENT 10046でのSQLトレースでバインド変数を見る

バインド変数の値を見る - ablog のつづき。

EVENTはOracleの内部動作変更や、デバッグなどに使用されるものであり、正式にサポートされるものではありません。使用する場合は、自己責任において使用してください。

Oracle SQLチューニング講座(5):SQLチューニングの基盤となる統計情報 (2/4) - @IT

とのこと。
EVENT 10046でのSQLトレースでバインド変数を確認してみた。


SQL*Plus でログインする。

$ sqlplus scott/tiger
SQL> select userenv('SESSIONID') from dual;

EVENT 10046のSQLトレースを取得するよう設定する。

$ sqlplus / as sysdba
SQL> set linesize 200
SQL> col process for a10
SQL> col sql_text for a70
SQL> select sid, serial#, process, sql_hash_value, sql_address, sql_text 
 from v$session a, v$sqltext b  
 where a.sql_address = b.address and a.sql_hash_value = b.hash_value;
       SID    SERIAL# PROCESS    SQL_HASH_VALUE SQL_ADDR SQL_TEXT
---------- ---------- ---------- -------------- -------- -----------------------------------
       188        381 1356            160872446 60E9EB90 ess and a.sql_hash_value = b.hash_value
       188        381 1356            160872446 60E9EB90 ext  from v$session a, v$sqltext b  where a.sql_address = b.addr
       188        381 1356            160872446 60E9EB90 select sid, serial#, process, sql_hash_value, sql_address, sql_t
       189          7 1234           4281219134 60C71F7C BEGIN EMD_NOTIFICATION.QUEUE_READY(:1, :2, :3); END;
       192         78 1354            572018883 5CE56A3C select userenv('SESSIONID') from dual

SQL> EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(192,78,TRUE);
SQL> EXECUTE DBMS_SYSTEM.SET_EV(192,78,10046,12,'');

バインド変数を使ってSQLを実行する。

SQL> variable v1 char(3);
SQL> exec :v1 := '001';
SQL> select * from emp where id =:v1;

ID     NAME
------ --------------------
001    scott

SQLトレースの設定を解除する。

SQL> EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(192,78,FALSE);
SQL> EXECUTE DBMS_SYSTEM.SET_EV(192,78,10046,0,'');

SQLトレースを確認する。

$ sqlplus / as sysdba
SQL> select value from v$parameter where name='user_dump_dest';

VALUE
--------------------------------------------------------------------------------
/export/home/oracle/admin/orcl/udump
SQL> exit
$ cd /export/home/oracle/admin/orcl/udump
$ cat orcl_ora_1355.trc 
/export/home/oracle/admin/orcl/udump/orcl_ora_1355.trc
Oracle Database 10g Release 10.2.0.4.0 - Production
ORACLE_HOME = /export/home/oracle/product/10.2.0/db_1
System name:    SunOS
Node name:      solaris101
Release:        5.10
Version:        Generic_137138-09
Machine:        i86pc
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 18
Unix process pid: 1355, image: oracle@solaris101 (TNS V1-V3)

*** 2009-05-30 02:39:55.456
*** ACTION NAME:() 2009-05-30 02:39:55.456
*** MODULE NAME:(SQL*Plus) 2009-05-30 02:39:55.456
*** SERVICE NAME:(SYS$USERS) 2009-05-30 02:39:55.456
*** SESSION ID:(192.78) 2009-05-30 02:39:55.455
=====================
PARSING IN CURSOR #2 len=26 dep=0 uid=32 oct=47 lid=32 tim=1732854257 hv=1566695
677 ad='60e261fc'
BEGIN :v1 := '001'; END;
END OF STMT
PARSE #2:c=10000,e=324,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1732853895
BINDS #2:
kkscoacd
 Bind#0
  oacdty=96 mxl=06(06) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=832 siz=8 off=0
  kxsbbbfp=fde9fe1c  bln=06  avl=00  flg=05
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3
=0 obj#=-1 tim=1732858816
EXEC #2:c=0,e=3539,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1732859068
*** 2009-05-30 02:40:07.775
WAIT #2: nam='SQL*Net message from client' ela= 12025517 driver id=1650815232 #b
ytes=1 p3=0 obj#=-1 tim=1744884704
=====================
PARSING IN CURSOR #3 len=31 dep=0 uid=32 oct=3 lid=32 tim=1744885325 hv=33342276
42 ad='60e25b90'
select * from emp where id =:v1
END OF STMT
PARSE #3:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1744885317
BINDS #3:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=832 siz=32 off=0
  kxsbbbfp=fde9fe04  bln=32  avl=03  flg=05
  value="001"
EXEC #3:c=0,e=779,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1744886225
WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3
=0 obj#=-1 tim=1744886307
FETCH #3:c=0,e=210,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=1744886573
WAIT #3: nam='SQL*Net message from client' ela= 543 driver id=1650815232 #bytes=
1 p3=0 obj#=-1 tim=1744887211
FETCH #3:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1744887299
WAIT #3: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3
=0 obj#=-1 tim=1744887344

$ tkprof orcl_ora_1355.trc 1355.prf explain=scott/tiger aggregate=no sys=no sort=fchela
$ cat 1355.prf
TKPROF: Release 10.2.0.4.0 - Production on Sat May 30 02:42:09 2009

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: orcl_ora_1355.trc
Sort options: fchela  
********************************************************************************
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
--------------------------------------------------------------------------------

*** SESSION ID:(192.78) 2009-05-30 02:39:55.455

********************************************************************************

select * 
from
 emp where id =:v1


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        2      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          2          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 32  (SCOTT)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      0   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'EMP' (TABLE)
      0    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'SYS_C004426' (INDEX 
               (UNIQUE))


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

BEGIN :v1 := '001'; END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 32  (SCOTT)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       12.02         12.02



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           1
Fetch        2      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.00          0          2          0           2

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     2       12.02         12.02


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

    2  user  SQL statements in session.
    0  internal SQL statements in session.
    2  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_1355.trc
Trace file compatibility: 10.01.00
Sort options: fchela  
       1  session in tracefile.
       2  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       2  SQL statements in trace file.
       2  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           SCOTT.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
      51  lines in trace file.
      12  elapsed seconds in trace file.

[参考]
Oracle SQLチューニング講座(5):SQLチューニングの基盤となる統計情報 (2/4) - @IT