10046事件与tkprof命令

在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       <ospid>                   Set OS pid of process to debug
SETORAPID      <orapid> ['force']        Set Oracle pid of process to debug
SHORT_STACK                              Dump abridged OS stack
DUMP           <dump_name> <lvl> [addr]  Invoke named dump
DUMPSGA        [bytes]                   Dump fixed SGA
DUMPLIST                                 Print a list of available dumps
EVENT          <text>                    Set trace event in process
SESSION_EVENT  <text>                    Set trace event in session
DUMPVAR        <p|s|uga> <name> [level]  Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE       <address> <type> <count>  Print/dump an address with type info
SETVAR         <p|s|uga> <name> <value>  Modify a fixed PGA/SGA/UGA variable
PEEK           <addr> <len> [level]      Print/Dump memory
POKE           <addr> <len> <value>      Modify memory
WAKEUP         <orapid>                  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             <Inst-List | def | all>   Parallel oradebug command prefix
-R             <Inst-List | def | all>   Parallel oradebug prefix (return output
SETINST        <instance# .. | all>      Set instance list in double quotes
SGATOFILE      <SGA dump dir>         Dump SGA to file; dirname in double quotes
DMPCOWSGA      <SGA dump dir> Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA      <SGA dump dir>         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      <ifname>  <ofname>        Helps translate PCs to names
WATCH          <address> <len> <self|exist|all|target>  Watch a region of memory
DELETE         <local|global|target> watchpoint <id>    Delete a watchpoint
SHOW           <local|global|target> 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           <func> [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: oracle@even.oracle.com (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命令翻译后的内容更加直观，容易懂，而且内容显示的执行计划是我们熟悉的形式。