10046事件和tkprof命令

    使用10046事件是在oralce数据库中查看目标sql的执行计划的另外一种方法。这种方法与使用explain plan命令，dbms_xplan包和autotrace开关的不同之处在于，所得到的执行计划的中明确显示了目标sql实际执行计划中每一个执行步骤所消耗的逻辑读，物理读和花费的时间。这种细粒度的明细显示在我们诊断复杂sql的性能问题时尤为有用，而且这也是其他三种方法所不能提供的（实际上，用gather_plan_statistisc hint配合dbms_xplan包一起使用也可也达到类似的10046事件这种细粒度的明细显示效果）

    用10046事件得到目标sql的执行计划是很容易的，只需要依次执行如下三个步骤：

    首先在当前session中激活10046事件

    接着在此session中执行目标sql

    最后在此session中关闭10046事件

    当执行完上述步骤后，oracle就会将目标sql的执行计划和明细资源消耗写入此session所对应的trace文件中，查看这个trace文件就能知道目标sql的执行计划和资源消耗明细了。oracle会在参数user_dump_dest所代表的的目标下生成trace文件，其命名格式为“实例名_ora_当前session的spid.trc”.

    通常可以使用如下两种方法在当前session中激活10046事件：

    在当前seesion中执行alter session set events ‘10046 trace name context forever，level 12’

    在当前session中执行oradebug event 10046 trace name context forever,level 12.

    需要注意的是，10046事件所产生的的原始trace文件我们习惯称之为裸trace文件，oracle记录在裸trace文件中的内容一眼看上去并不是那么直观，也不是那么容易能看懂。为了让上述裸trace文件能够以一种更直观，更容易懂的方式展现出来，oracle提供了tkprof命令，这个命令式oralce自带的，可以用来翻译上述trace文件。从随后的实例中可以看到，翻译后的更加直观，更容易懂了。

    我们还是以目标sql语句“select empno,ename,dname from emp a,dept b where a.deptno=b.deptno;”为例来说明10046事件和thprof命令的用法。

    oradebug setmypid表示准备对当前session使用oradebug命令：

SQL> oradebug setmypid;

Statement processed.

    这里我们使用了之前的介绍的第二种方法在当前session中激活10046事件：

SQL> oradebug event 10046 trace name context forever,level 12;

Statement processed.

    在当前session中激活了10046事件后，执行目标sql：

SQL> select empno,ename,dname from scott.emp a,scott.dept b where a.deptno=b.deptno;

     EMPNO ENAME      DNAME

---------- ---------- --------------

      7782 CLARK      ACCOUNTING

      7839 KING       ACCOUNTING

      7934 MILLER     ACCOUNTING

      7566 JONES      RESEARCH

      7902 FORD       RESEARCH

      7876 ADAMS      RESEARCH

14 rows selected.

    用oradebug tracefile_name命令可以一目了然地看到当前session激活10046事件后所对应的trace文件的路径和名称：

SQL> oradebug tracefile_name;

/u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_10292.trc

    原始的trace文件一眼看上去不是太直观，也不是太容易看动懂。现在我们用tkprof命令来翻译一下：

[oracle@node1 ~]$ tkprof /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_10292.trc

output = /home/oracle/mecbs_10046.trc

oracle@node1 ~]$ cat mecbs_10046.trc 

TKPROF: Release 11.2.0.4.0 - Development on Sun Dec 14 16:00:53 2014

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_10292.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

SQL ID: 0rqws2b4fvrr6 Plan Hash: 844388907

select empno,ename,dname 

from

 scott.emp a,scott.dept b where a.deptno=b.deptno

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.02       0.07          0        260          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.00       0.00          0         10          0          14

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total        4      0.02       0.07          0        270          0          14

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: SYS

Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        14         14         14  MERGE JOIN  (cr=10 pr=0 pw=0 time=313 us cost=6 size=364 card=14)

         4          4          4   TABLE ACCESS BY INDEX ROWID DEPT (cr=4 pr=0 pw=0 time=256 us cost=2 size=52 card=4)

         4          4          4    INDEX FULL SCAN PK_DEPT (cr=2 pr=0 pw=0 time=143 us cost=1 size=0 card=4)(object id 87107)

        14         14         14   SORT JOIN (cr=6 pr=0 pw=0 time=184 us cost=4 size=182 card=14)

        14         14         14    TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=125 us cost=3 size=182 card=14)