千家信息网

10046事件和tkprof命令

发表于:2024-11-28 作者:千家信息网编辑
千家信息网最后更新 2024年11月28日,使用10046事件是在oralce数据库中查看目标sql的执行计划的另外一种方法。这种方法与使用explain plan命令,dbms_xplan包和autotrace开关的不同之处在于,所得到的执行
千家信息网最后更新 2024年11月28日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)

0