oracle sql trace與10046淺談

 文件也寫的很清楚了，是一個基礎的sql效能診斷工具，sql_trace工具可以評估sql語句的執行效率，並且通過TKPROF工具生成易讀統計報表，
因為直接生成到trace目錄中的資訊我們看起來不太直觀，所以這裡是oracle推薦兩個工具一先一後輔助而生。我們這裡的環境是11g的，所以
比10g的trace 資訊存放目錄要多一些，看你自己的輸出目錄了我存放的是/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace
可以通過sql命令啟動SQL_TRACE，或者在初始化引數裡面，檢視官方文件，裡面有寫

檢視當前預設的trace檔案是哪一個，用sql語句查詢，如下：

SELECT      d.VALUE

         || '/'

         || LOWER (RTRIM (i.INSTANCE, CHR (0)))

         || '_ora_'

         || p.spid

         || '.trc'

            AS "trace_file_name"

  FROM   (SELECT   p.spid

            FROM   v$mystat m, v$session s, v$process p

           WHERE   m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

         (SELECT   t.INSTANCE

            FROM   v$thread t, v$parameter v

           WHERE   v.NAME = 'thread'

                   AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

         (SELECT   VALUE

            FROM   v$parameter

           WHERE   NAME = 'user_dump_dest') d;

SQL> SELECT      d.VALUE
  2           || '/'
         || LOWER (RTRIM (i.INSTANCE, CHR (0)))
         || '_ora_'
         || p.spid
         || '.trc'
            AS "trace_file_name"
  FROM   (SELECT   p.spid
            FROM   v$mystat m, v$session s, v$process p
           WHERE   m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,
         (SELECT   t.INSTANCE
            FROM   v$thread t, v$parameter v
           WHERE   v.NAME = 'thread'
                   AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,
         (SELECT   VALUE
            FROM   v$parameter
           WHERE   NAME = 'user_dump_dest') d;    

trace_file_name
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_3276808.trc
知道trace資訊放哪了
SQL>alter session set sql_trace=true;  開啟當前會話級別的操作，關閉為false

或者

SQL>alter system set sql_trace=true;開啟這個資料庫層面的很少用到，這樣會生成大量的trace資訊，沒必要而且對資料庫執行壓力比較大，不推薦

我們用示例來看一下
SQL> alter session set sql_trace=true;
Session altered.

SQL> select * from t;
71176 rows selected.

  關閉SQL_TRACE

SQL> alter session set sql_trace=false;

我們去檢視trace檔案資訊，主要包擴了Parse/Fetch/Execute三個階段
trace檔案頭
Trace file /u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_5767668.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name:    AIX
Node name:      cecgt
Release:        1
Version:        6
Machine:        00CF2CD34C00
Instance name: xupeng11g
Redo thread mounted by this instance: 1
Oracle process number: 19
Unix process pid: 5767668, image: oracle@cecgt (TNS V1-V3)
主要trace資訊
=====================
PARSING IN CURSOR #4 len=15 dep=0 uid=0 oct=3 lid=0 tim=6847984458 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #4:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984456
EXEC #4:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984589
FETCH #4:c=0,e=86,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=6847984795
FETCH #4:c=0,e=37,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847985336
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847990552
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847995856
FETCH #4:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848001124
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848006350
FETCH #4:c=0,e=44,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848011101
FETCH #4:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848015655
.............................

STAT #4 id=1 cnt=71176 pid=0 pos=1 obj=73439 op='TABLE ACCESS FULL T (cr=5703 pr=0 pw=0 time=48516 us cost=280 size=10469396 ca
rd=66262)'
*** 2014-02-11 11:17:43.546
CLOSE #4:c=0,e=27,dep=0,type=0,tim=7281805082
這個檔案的可讀性要差很多。 對這裡面的一些引數做些說明：

PARSING IN CURSOR 部分：   

                Len: 被解析SQL的長度

                Dep: 產生遞迴SQL的深度

                Uid：user id

                Otc: Oracle command type 命令的型別

                Lid: 私有使用者id

                Tim：時間戳

                Hv： hash value

                Ad：SQL address

 

PARSE,EXEC,FETCH 部分

                C: 消耗的CPU time

                E：elapsed time 操作的用時

                P: physical reads 物理讀的次數

                Cr: consistent reads 一致性方式讀取的資料塊

                Cu：current 方式讀取的資料塊

                Mis：cursor misss in cache 硬分析次數

                R: -rows 處理的行數

                Dep: depth 遞迴SQL的深度

                Og： optimizer goal 優化器模式

                Tim：timestamp時間戳

 

STATS 部分：

                Id: 執行計劃的行源號

                Cnt：當前行源返回的行數

                Pid：當前行源號的父號

                Pos：執行計劃中的位置

                Obj：當前操作的物件id（如果當前行原始一個物件的話）

                Op：當前行源的資料訪問操作

這種方式對於很少做優化的DBA來說那就看起來比較費勁了，有的人說看AWR報告我說沒有必要，你只需要檢視一個或者幾個，而AWR報告
是從資料庫最初的基線到資料庫使用週期的效能的評估報告。我們可以使用前面我推薦給大家的工具tkprof來整理一下凌亂的trace檔案
下面我介紹什麼是TKPROF？
Tkprof 工具是Oracle 自帶的一個工具，用於處理原始的trace檔案，它的作用主要是合併彙總trace檔案中的一些項，規範化檔案的格式，使檔案更具有可讀性

注意：tkprof 工具只能用在處理SQL_TRACE和10046事件（下節內容也會提到它）產生的trace，其他事件如10053不能處理。

我們看一下tkprof如何使用，我們可以查官方文件來看一下使用語法

屬於作業系統命令，我們執行一下

Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
 filename1 是指定的輸入檔案，可以是多個檔案聯起來
filename2 是格式化輸出檔案 
  SORT   在輸出到輸出檔案前，先程式排序。如果省去，則按照實際使用的順序輸出到檔案中。排序選項有以下多種：
  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

PRINT        只列出輸出檔案的第一個integer 的SQL語句。預設為所有的SQL語句。
AGGREGATE    如果= NO ，則不對多個相同的SQL進行彙總。
INSERT       SQL 語句的一種，用於將跟蹤檔案的統計資訊儲存到資料庫中。在TKPROF建立指令碼後，在將結果輸入到資料庫中。
SYS         禁止或啟用 將SYS使用者所釋出的SQL語句列表到輸出檔案中。
TABLE       在輸出到輸出檔案前，用於存放臨時表的使用者名稱和表名。
EXPLAIN     對每條SQL 語句確定其執行規劃。並將執行規劃寫到輸出檔案中。

其中比較有用的一個排序選項是fchela，即按照elapsed time fetching來對分析的結果排序（記住要設定初始化引數timed_statistics=true），生成的檔案將把最消耗時間的sql放在最前面顯示。另外一個有用的引數就是sys，這個引數設定為no可以阻止所有以sys使用者執行的sql被顯示出來，這樣可以減少分析出來的檔案的複雜度，便於檢視。
到這裡我們開始使用tkprof來格式化輸出一個trace檔案，我們用到上面的引數，看自己的需要了我這裡用的不多

$ tkprof xupeng11g_ora_5767668.trc xupengtrace.txt sys=no
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
$ ls -ltr
total 8584
-rw-r-----    1 oracle   oinstall      27698 Feb 11 11:17 xupeng11g_ora_5767668.trm
-rw-r-----    1 oracle   oinstall     405360 Feb 11 11:17 xupeng11g_ora_5767668.trc
-rw-r--r--    1 oracle   oinstall       2706 Feb 11 12:44 xupengtrace.txt
$ more xupengtrace.txt
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
Trace file: xupeng11g_ora_5767668.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
********************************************************************************
# 以上檔案頭資訊描述了tkprof的版本資訊，以及報告中一些列的含義
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS 非遞迴sql
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch     4747      0.00       0.16          0       5703          0       71176
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4752      0.00       0.16          0       5703          0       71176
Misses in library cache during parse: 1  #shared pool 中沒有命令，說明做了1次硬解析
Misses in library cache during execute: 1 也執行了一次sql
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS  遞迴SQL語句
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0
Misses in library cache during parse: 0
    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
********************************************************************************
Trace file: xupeng11g_ora_5767668.trc
Trace file compatibility: 11.1.0.7
Sort options: default
     473  elapsed seconds in trace file.
    4912  lines in trace file.
       3  unique SQL statements in trace file.
       3  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  user  SQL statements in trace file.
       1  session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
    3  SQL statements in session.
    0  internal SQL statements in session.
    3  user  SQL statements in session.
Misses in library cache during parse: 0
total        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Fetch        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Parse        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
call     count       cpu    elapsed       disk      query    current        rows
     473  elapsed seconds in trace file.
    4912  lines in trace file.
       3  unique SQL statements in trace file.
       3  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  user  SQL statements in trace file.
       1  session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
    3  SQL statements in session.
    0  internal SQL statements in session.
    3  user  SQL statements in session.
Misses in library cache during parse: 0
total        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Fetch        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Parse        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
call     count       cpu    elapsed       disk      query    current        rows

tkprof就可以方便我們檢視trace資訊了！！！ 有種高階大氣上檔次的趕腳，哈哈。
下面我們還要談談10046事件，sql_trace其實已經包含了Parse/Fetch/Execute三個階段，而10046 比 SQL_TRACE引數提供更多的控制選項， 更詳細的內容輸出，這個才是我們最終
為什麼要選擇10046事件做sql調優的原因。而且本人也推薦大家兩種方法都測試一下，根據你所需要的吧，這裡我不進行過多的分析了！我們繼續，
10046 trace

10046 trace幫助我們解析 一條/多條SQL、PL/SQL語句的執行狀態 ，這些狀態包括 ：Parse/Fetch/Execute三個階段中遇到的等待事件、消耗的物理和邏輯讀、CPU時間、執行計劃等等。
10046 為我們揭示了 一條/多條SQL 的執行情況， 對於  以點入手的 SQL調優是很好的輔助工具，10046還能幫助我們分析 一些 DDL維護命令的內部工作原理， RMAN、Data Pump Expdp/Impdp等工具的緩慢問題等

10046 TRACE的LEVEL:

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

• 1  啟用標準的SQL_TRACE功能 ( 預設)  包含了 SQL語句、響應時間、服務時間、處理的行數，物理讀和寫的數目、執行計劃以及其他一些額外資訊。   到版本10.2中 執行計劃寫入到 trace 的條件是僅當相關遊標 已經關閉時， 且與之相關的執行統計資訊是所有執行次數的總和資料。  到版本11.1中僅在每次遊標的第一次執行後將執行計劃寫入到trace ， 執行統計資訊僅僅和這第一次執行相關
• 4 比level 1時多出 繫結變數的 trace
• 8  比level 1多出等待事件，特別對於9i中指出 latch free等待事件很有用，對於分析全表掃描和索引掃描也很有用
• 12  比level 1 多出 繫結變數和 等待事件
• 16  在11g中為每一次執行生成STAT資訊，僅在11.1之後可用
• 32  比level 1少執行計劃
•  64  和level 1 相比 在第一次執行後還可能生成執行計劃資訊 ； 條件是某個遊標在前一次執行的前提下 執行耗時變長了一分鐘。僅在 11.2.0.2中可用
• Level 28 (4 + 8 + 16) 代表 同時啟用 level 4 、level 8、level 16
• level 68 ( 64 + 4 )  代表 同時啟用 level 64、level 4

我做在做一個示例
SQL> alter session set events '10046 trace name context forever,level 28';
Session altered.

執行一個事務查詢
select * from t；
檢視trace檔案內容
PARSING IN CURSOR #2 len=15 dep=0 uid=0 oct=3 lid=0 tim=15535564761 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564760
EXEC #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564873
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535564964
FETCH #2:c=0,e=141,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=15535565149
WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565662
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565701
FETCH #2:c=0,e=61,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535565752
WAIT #2: nam='SQL*Net message from client' ela= 5257 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571040
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571084
FETCH #2:c=0,e=52,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535571126
WAIT #2: nam='SQL*Net message from client' ela= 5228 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576386
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576425
FETCH #2:c=0,e=72,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535576487
WAIT #2: nam='SQL*Net message from client' ela= 5382 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581907
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581945
FETCH #2:c=0,e=54,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535581989
WAIT #2: nam='SQL*Net message from client' ela= 5166 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587185
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587229
Bind#2
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f9ccfec6bd8  bln=22  avl=04  flg=05
我們可以再一次使用tkprof來格式化輸出一個檔案，方法已經介紹了。我們可以對比一下sql_trace與10046的區別了，10046更加的完善了，
包括變數、WAIT Time等。推薦大家使用10046 trace我們sql_trace和10046就淺談到這裡。後續我會把oradebug工具也推薦給大家，近期
我在整理一下頭緒。