EVENT 10046でのSQLトレースとTKPROF
1. EVENT 10046

EVENT 10046はOracleに提供された内部イベントで、SQL_TRACEを強化する機能となる。

EVENT 10046のレベル
レベル 内容
LEVEL 1 SQL_TRACE機能と同等
LEVEL 4 LEVEL 1 + バインド変数情報が出力される
LEVEL 8 LEVEL 1 + 待機イベント情報が出力される
LEVEL 12 LEVEL 1 + LEVEL 4 + LEVEL 8
使用上の注意事項
  • DBサーバーに負荷をかけるので、本番での使用を慎重に検討すべき
  • MAX_DUMP_FILE_SIZEによってトレースファイルサイズが制限されてるかどうかを確認
  • TIMED_STATISTICS=TRUEを設定しているかどうかを確認
2. EVENT 10046トレースの使用
2.1 インスタンスレベルでEVENT 10046の使用

パラメータファイルにEVENTパラメータを設定

event="10046 trace name context forever,level 12"
2.2 現行セッションに対してEVENT 10046トレースを使用
FFM(DBADMIN)> alter session set events '10046 trace name context forever, level 12';

Session altered.

FFM(DBADMIN)> select count(*) from dba_objects;

  COUNT(*)
----------
     10280

FFM(DBADMIN)> alter session set events '10046 trace name context off';

Session altered.

FFM(DBADMIN)>

トレースファイル名を取得
FFM(DBADMIN)> SELECT    d.VALUE
       || '/'
       || LOWER (RTRIM (i.INSTANCE, CHR (0)))
       || '_ora_'
       || p.spid
       || '.trc' trace_file_name
  FROM (SELECT p.spid
          FROM v$mystat m, v$session s, v$process p
         WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,
       (SELECT t.INSTANCE
          FROM v$thread t, v$parameter v
         WHERE v.NAME = 'thread'
           AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,
       (SELECT VALUE
          FROM v$parameter
         WHERE NAME = 'user_dump_dest') d
/

TRACE_FILE_NAME
--------------------------------------------------------------------------------------------------------
/u01/oracle/app/admin/FFM/udump/ffm_ora_17296.trc

FFM(DBADMIN)>
2.3 別セッションに対してEVENT 10046トレースを使用

DBADMINユーザーでDBに接続

[~ oracle(FFM)] sqlplus dbadmin/oracle

SQL*Plus: Release 10.2.0.4.0 - Production on \u91d1 2\u6708 12 16:02:21 2010

Copyright (c) 1982, 2007, Oracle.  All Rights Reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

FFM(DBADMIN)>

SYSユーザーでDBに接続してDBADMINユーザーのセッションに対してDBMS_SYSTEM.SET_EVで10046トレースを開始する
FFM(SYS)> select sid,serial#,username from v$session where username is not null;

       SID    SERIAL# USERNAME
---------- ---------- ------------------------------------------------------------------------------------------
       300       3277 SYS
       305       2652 DBADMIN
       306       2854 SYS
       308         53 DBSNMP
       310         39 DBSNMP
       311          3 DBSNMP

8 rows selected.

FFM(SYS)> EXEC DBMS_SYSTEM.SET_EV(305,2652,10046,12,'');

PL/SQL procedure successfully completed.

FFM(SYS)>

DBADMINのセッションで何らかのSQLを実行する
FFM(DBADMIN)> select count(*) from dba_objects;

  COUNT(*)
----------
     10280

FFM(DBADMIN)> /

  COUNT(*)
----------
     10280

FFM(DBADMIN)> select count(*) from dba_objects,dba_objects;

  COUNT(*)
----------
 105678400

FFM(DBADMIN)>

DBADMINユーザーのセッションに対してDBMS_SYSTEM.SET_EVで10046トレースを停止
FFM(SYS)> EXEC DBMS_SYSTEM.SET_EV(305,2652,10046,0,'');

PL/SQL procedure successfully completed.

FFM(SYS)>
3. TKPROFの使用

TKPROFでトレースファイルを変換

[udump oracle()] pwd
/u01/oracle/app/admin/FFM/udump
[udump oracle()] ls -l
\u5408\u8a08 8
-rw-r-----  1 oracle oinstall 7765  2\u6708 12 16:23 ffm_ora_18348.trc
[udump oracle()] tkprof ffm_ora_18348.trc ffm_ora_18348.txt

TKPROF: Release 10.2.0.4.0 - Production on \u91d1 2\u6708 12 16:25:21 2010

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

[udump oracle()]

レポート表示例
[udump oracle()] more ffm_ora_18348.txt

TKPROF: Release 10.2.0.4.0 - Production on \u91d1 2\u6708 12 16:25:21 2010

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

Trace file: ffm_ora_18348.trc
Sort options: default

********************************************************************************
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
********************************************************************************

select count(*)
from
 dba_objects

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.04       0.04          0       2312          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.04          0       2312          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 29

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2312 pr=0 pw=0 time=42105 us)
  10280   VIEW  DBA_OBJECTS (cr=2312 pr=0 pw=0 time=83333 us)
  10280    UNION-ALL  (cr=2312 pr=0 pw=0 time=73051 us)
  10278     FILTER  (cr=2307 pr=0 pw=0 time=52476 us)
  10565      HASH JOIN  (cr=132 pr=0 pw=0 time=32776 us)
     31       TABLE ACCESS FULL USER$ (cr=4 pr=0 pw=0 time=133 us)
  10565       TABLE ACCESS FULL OBJ$ (cr=128 pr=0 pw=0 time=10665 us)
    958      TABLE ACCESS BY INDEX ROWID IND$ (cr=2175 pr=0 pw=0 time=16196 us)
   1086       INDEX UNIQUE SCAN I_IND1 (cr=1088 pr=0 pw=0 time=6506 us)(object id 39)
      2     NESTED LOOPS  (cr=5 pr=0 pw=0 time=67 us)
      2      INDEX FULL SCAN I_LINK1 (cr=1 pr=0 pw=0 time=32 us)(object id 107)
      2      TABLE ACCESS CLUSTER USER$ (cr=4 pr=0 pw=0 time=33 us)
      2       INDEX UNIQUE SCAN I_USER# (cr=2 pr=0 pw=0 time=13 us)(object id 11)

Elapsed times include waiting on following events:
... ...
Unless otherwise stated, the content of this page is licensed under Creative Commons Attribution-ShareAlike 3.0 License