EVENT 10046取SQL trace的方法和TKPOF整形

1.EVENT 10046

EVENT 10046是Oracle提供的内部event，是强化SQL_TRACE的功能。

EVENT 10046 level

level	内容
LEVEL 1	与SQL_TRACE等同
LEVEL 4	LEVEL 1 + 绑定变量信息输出
LEVEL 8	LEVEL 1 + 待机event信息输出
LEVEL 12	LEVEL 1 + LEVEL 4 + LEVEL 8

注意事项
对DB造成额外的负载，在生产库中的使用需要谨慎。
请确认是否设定了MAX_DUMP_FILE_SIZE
请确认是否设定了TIMED_STATISTICS=TRUE

2.EVENT 10046的使用
2.1 在实例级别使用EVENT 10046

在spfile或者pfile中设定EVENT参数

event="10046 trace name context forever,level 12"

2.2 在session级别使用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)>

取得trace 文件名

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

2.3 对其它session使用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的session用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用户的session中执行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)>

用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对trace文件整形。

[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()]

生成的10046文件示例：

[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:
... ...