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)