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)