Oracle 10046事件 介紹(一)

做Oracle方面的工作時間長了，經常會聽人提起10046事件，尤其是涉及到SQL調優的時候更甚。那10046事件到底是什么呢，先做一個簡單的介紹。

1、什么是10046事件

  10046事件是Oracle提供的一個用于分析性能的工具，它能幫助我們解析一條/多條SQL、PL/SQL語句的運行狀態，這些狀態包括 ：Parse/Fetch/Execute三個階段中遇到的等待事件、消耗的物理和邏輯讀、CPU時間、執行計劃等等。

2、10046事件的Level

不同的Level對應不同的跟蹤級別

• 1 啟用標準的SQL_TRACE功能(默認)包含了SQL語句、響應時間、服務時間、處理的行數，物理讀和寫的數目、執行計劃以及其他一些額外信息。到版本10.2中執行計劃寫入到trace的條件是僅當相關游標已經關閉時，且與之相關的執行統計信息是所有執行次數的總和數據。到版本11.1中僅在每次游標的第一次執行后將執行計劃寫入到trace，執行統計信息僅僅和這第一次執行相關

• 4 比level 1時多出綁定變量的trace

• 8 比level 1多出等待事件，特別對于9i中指出latchfree等待事件很有用，對于分析全表掃描和索引掃描也很有用

• 12 比level 1多出綁定變量和等待事件

11g及以上版本

• 16 在11g中為每一次執行生成STAT信息

• 32 比level 1少執行計劃

11.2.0.2及以上版本

• 64 和level 1相比在第一次執行后還可能生成執行計劃信息；條件是某個游標在前一次執行的前提下運行耗時變長了一分鐘。

3、啟用10046事件

1)對本session啟用10046事件

a.

 alter session set events '10046 trace name context forever,level 12'

b. 

 oradebug setmypid

 oradebug event 10046 trace name context ,level 12

其中能修改的只有level級別

2)對其他session啟用10046事件

oradebug setospid|setorapid xxx

oradebug event 10046 trace name context ,level 12

4、停用10046事件

分別對應上面不同的啟用方式

alter session set events '10046 trace name context forever off'

oradebug event 10046 trace name context off

或者退出啟用10046事件的session

5、獲取10046事件生成的trace文件

a.對于11g及以上的版本，使用如下語句可以輕松得到

select value from v$diag_info where name='Default Trace File';

b.對于10g及以前的版本中需要使用如下sql

SELECT D.VALUE || '' || LOWER(RTRIM(I.INSTANCE, CHR(0))) || '_ora_' ||
       P.SPID || '.trc' TRACE_FILE_NAME
  FROM (SELECT P.SPID
          FROM SYS.V$MYSTAT M, SYS.V$SESSION S, SYS.V$PROCESS P
         WHERE M.STATISTIC# = 1
           AND S.SID = M.SID
           AND P.ADDR = S.PADDR) P,
       (SELECT T.INSTANCE
          FROM SYS.V$THREAD T, SYS.V$PARAMETER V
         WHERE V.NAME = 'thread'
           AND (V.VALUE = 0 OR T.THREAD# = TO_NUMBER(V.VALUE))) I,
       (SELECT VALUE FROM SYS.V$PARAMETER WHERE NAME = 'user_dump_dest') D;

c.如果使用oradebug命令則使用相對應的oradebug tracefile_name即可得到trace文件

6、格式化trace文件

 10046事件所產生的原始trace文件習慣稱之為裸trace文件(raw trace)，Oracle記錄在裸trace文件中的內容一眼看上去并不是那么觀，也不是那么容易看懂。為了祼trace文件能夠以一種更直觀、更容易懂的方式展現出來，Oracle提供了tkprof命令，這個命令是Oracle自帶的，可以用它來翻譯祼trace文件。

tkprof的語法如下：

[oracle@rhel6 10046]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
    userid  userid of user that parsed the cursor

7、簡單示例，數據庫版本11.2.0.4

zx@ORCL>alter session set events '10046 trace name context forever,level 12';

Session altered.

zx@ORCL>select * from scott.emp;

     EMPNO ENAME			  JOB				     MGR HIREDATE		    SAL       COMM     DEPTNO
---------- ------------------------------ --------------------------- ---------- ------------------- ---------- ---------- ----------
      7369 SMITH			  CLERK 			    7902 1980-12-17 00:00:00	    800 		   20
      7499 ALLEN			  SALESMAN			    7698 1981-02-20 00:00:00	   1600        300	   30
      ......

14 rows selected.

zx@ORCL>alter session set events '10046 trace name context off';

Session altered.

zx@ORCL>select value from v$diag_info where name='Default Trace File';

VALUE
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
/u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc

zx@ORCL>!
[oracle@rhel6 trace]$ tkprof /u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc 10046.trc

TKPROF: Release 11.2.0.4.0 - Development on Thu Feb 16 21:38:57 2017

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@rhel6 trace]$ cat 10046.trc

TKPROF: Release 11.2.0.4.0 - Development on Thu Feb 16 21:38:57 2017

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: /u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.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: ggqns3c1jz86c Plan Hash: 3956160932

select * 
from
 scott.emp


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          7          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          7          0          14

Misses in library cache during parse: 0
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  TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=81 us cost=3 size=532 card=14)


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

......省略部分內容

參考文檔：https://blogs.oracle.com/askmaclean/entry/maclean教你讀oracle_10046_sql_trace

MOS文檔EVENT: 10046 "enable SQL statement tracing (including binds/waits)" (文檔 ID 21154.1)

How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues (文檔 ID 376442.1)

官方文檔：http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94981