10046事件与tkprof命令

在ORACLE数据库里，我们通常可以使用如下这些方法(包括但不限于)得到目标SQL的执行计划： 1，explain plan 2，DBMS_XPLAN包 3，SQLPLUS中的AUTOTRACE开关 4，10046事件 5，10053事件 6，AWR报告或者STATSPACK报告 前面的四种方法比较普遍。 下面我来介绍下第

在ORACLE数据库里，我们通常可以使用如下这些方法(包括但不限于)得到目标SQL的执行计划：

1，explain plan

2，DBMS_XPLAN包

3，SQLPLUS中的AUTOTRACE开关

4，10046事件

5，10053事件

6，AWR报告或者STATSPACK报告

前面的四种方法比较普遍。

下面我来介绍下第四种即10046事件如何得到目标SQL的执行计划

10046与使用explain plan命令，DBMS_XPLAN包和AUTOTRACE开关的不同之处在于，所得到的执行计划中明确显示了目标SQL的实际执行计划中每一个步骤所消耗的逻辑度(cr:consistent read)，物理读(pr:physical read)和花费的时间(time)。

用10046事件得到的目标SQL的执行计划只需要依次执行下面三步：

在当前SESSION中激活10046事件在此SESSION中执行目标SQL在此SESSION中关闭10046事件

执行完上面的步骤后，ORACLE会将目标SQL的执行计划和明细资源消耗写入此SESSION对应的TRACE文件中，此文件一把会在USER_DUMP_DEST目录下，其命名格式是： 实例名_ora_当前SESSION的SPID.trc.

通常可以用下面两种方法激活10046事件：

在当前SESSION中执行alter session set events '10046 trace name context forever,level 12'在当前SESSION中执行oradebug event 10046 trace name context forever,level 12

本人偏向喜欢用第二中，因为可以在激活10046事件后，执行命令oradebug tracefile_name来得到当前SESSION所对应的trace文件的具体路径和名称

对应的在当前SESSION中关闭10046事件的方法为：

alter session set events '10046 trace name context off'oradebug event 10046 trace name context off

10046生成的TRACE文件，我们称之为裸文件(raw trace),ORACCLE 提供了工具TKPROF来查看他。下面我们来做一个实验来演示如何通过10046事件来获取和查看目标SQL的实际执行计划

下面我以目标SQL： "select empno,ename,dname from scott.emp,scott.dept where emp.deptno=dept.deptno" 为例子来说明10046事件和TKPROF的用法

SQL> oradebug help
HELP [command] Describe one or all commands
SETMYPID Debug current process
SETOSPID Set OS pid of process to debug
SETORAPID ['force'] Set Oracle pid of process to debug
SHORT_STACK Dump abridged OS stack
DUMP [addr] Invoke named dump
DUMPSGA [bytes] Dump fixed SGA
DUMPLIST Print a list of available dumps
EVENT Set trace event in process
SESSION_EVENT Set trace event in session
DUMPVAR

[level] Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE

Print/dump an address with type info
SETVAR

Modify a fixed PGA/SGA/UGA variable
PEEK [level] Print/Dump memory
POKE Modify memory
WAKEUP Wake up Oracle process
SUSPEND Suspend execution
RESUME Resume execution
FLUSH Flush pending writes to trace file
CLOSE_TRACE Close trace file
TRACEFILE_NAME Get name of trace file
LKDEBUG Invoke global enqueue service debugger
NSDBX Invoke CGS name-service debugger
-G Parallel oradebug command prefix
-R Parallel oradebug prefix (return output
SETINST Set instance list in double quotes
SGATOFILE Dump SGA to file; dirname in double quotes
DMPCOWSGA Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA Map SGA as COW; dirname in double quotes
HANGANALYZE [level] [syslevel] Analyze system hang
FFBEGIN Flash Freeze the Instance
FFDEREGISTER FF deregister instance from cluster
FFTERMINST Call exit and terminate instance
FFRESUMEINST Resume the flash frozen instance
FFSTATUS Flash freeze status of instance
SKDSTTPCS Helps translate PCs to names
WATCH

Watch a region of memory
DELETE watchpoint Delete a watchpoint
SHOW watchpoints Show watchpoints
CORE Dump core without crashing process
IPC Dump ipc information
UNLIMIT Unlimit the size of the trace file
PROCSTAT Dump process statistics
CALL [arg1] ... [argn] Invoke function with arguments
SQL> oradebug setmypid
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 12
Statement processed.

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

EMPNO ENAME DNAME
---------- ---------- --------------
7369 SMITH RESEARCH
7499 ALLEN SALES
7521 WARD SALES
7566 JONES RESEARCH
7654 MARTIN SALES
7698 BLAKE SALES
7782 CLARK ACCOUNTING
7788 SCOTT RESEARCH
7839 KING ACCOUNTING
7844 TURNER SALES
7876 ADAMS RESEARCH

EMPNO ENAME DNAME
---------- ---------- --------------
7900 JAMES SALES
7902 FORD RESEARCH
7934 MILLER ACCOUNTING

14 rows selected.

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

SQL> oradebug tracefile_name
/u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc

关掉10046事件：

SQL> oradebug event 10046 trace name context off
Statement processed.

查看/u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc文件

[oracle@even ~]$ vi /u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc
/u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining options
ORACLE_HOME = /u01/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: even.oracle.com
Release: 2.6.18-164.el5
Version: #1 SMP Thu Sep 3 02:16:47 EDT 2009
Machine: i686
Instance name: OMR
Redo thread mounted by this instance: 1
Oracle process number: 15
Unix process pid: 16192, image: [e-mail] (TNS V1-V3)

*** 2013-12-06 12:46:25.079
*** SERVICE NAME:(SYS$USERS) 2013-12-06 12:46:25.079
*** SESSION ID:(158.19) 2013-12-06 12:46:25.079

。。。。。。

。。。。。。

这样直接查看此文件，太难看了，格式很乱，不方便读。这个时候我们可以用ORACLE的TKPROF来格式化此文件，操作如下：

[oracle@even ~]$ tkprof /u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc /u01/app/oracle/admin/OMR/udump/watson_omr_ora_16192_tkprof.trc

TKPROF: Release 10.2.0.1.0 - Production on Fri Dec 6 12:57:28 2013

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

这个时候下面的格式就是格式化过的，方便读的

[oracle@even ~]$ vi /u01/app/oracle/admin/OMR/udump/watson_omr_ora_16192_tkprof.trc

TKPROF: Release 10.2.0.1.0 - Production on Fri Dec 6 12:57:28 2013

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

Trace file: /u01/app/oracle/admin/OMR/udump/omr_ora_16192.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
********************************************************************************

The following statement encountered a error during parse:

select empno,ename,dname,from scott.emp,scott.dept where emp.deptno=dept.deptno

Error encountered: ORA-00936
********************************************************************************

select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
spare2
from
obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
and linkname is null and subname is null
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.03 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.03 0 3 0 1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=157 us)
1 INDEX RANGE SCAN I_OBJ2 (cr=2 pr=0 pw=0 time=84 us)(object id 37)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net break/reset to client 2 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************

select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,
nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,
t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,
t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),
nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),
nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,
ts.logicalread
from
tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)

69,0-1 7%

。。。。。。

。。。。。。

我们可以看到，用tkprof命令翻译后的内容更加直观，容易懂，而且内容显示的执行计划是我们熟悉的形式。