バインド変数の値を見る - ablog のつづき。
EVENTはOracleの内部動作変更や、デバッグなどに使用されるものであり、正式にサポートされるものではありません。使用する場合は、自己責任において使用してください。
SQLチューニングの基盤となる統計情報 (2/4)：Oracle SQLチューニング講座（5） - ＠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.
