Oracle 10046事件 介紹(二) ---tkprof

    之前簡單的寫了10046事件介紹的文章http://hbxztc.blog.51cto.com/1587495/1898624，當然收集10046 trace不是最終的目的，能夠讀懂并且通過分析10046 trace進而分析相應sql的性能問題才是10046 trace真正發揮作用的地方。但是10046事件所產生的原始trace文件習慣稱之為裸trace文件(raw trace)，Oracle記錄在裸trace文件中的內容一眼看上去并不是那么觀，也不是那么容易看懂。為了祼trace文件能夠以一種更直觀、更容易懂的方式展現出來，Oracle提供了tkprof命令，這個命令是Oracle自帶的，可以用它來翻譯祼trace文件。

1、tkprof的語法：

tkprof filename1 filename2 [waits=yes|no] [sort=option] [print=n]
    [aggregate=yes|no] [insert=filename3] [sys=yes|no] [table=schema.table]
    [explain=user/password] [record=filename4] [width=n]

最簡單的使用方法是tkprof trace_filename output_filename

具體使用方法及參數含義參考官方文檔http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94985

tkprof生成的輸出文件中會包含一些Oracle內部調用的sql的trace記錄，這些SQL是由用戶的SQL觸發，一般來說是查一些數據字典基表例如 obj$、tab$等，常規情況下這些SQL運行消耗的資源和時間都非常少。我們不需要關心，我們關心的就是我們運行的sql所對應的各種信息。

2、一個簡單sql對應的trace經過tkprof后的示例

SQL ID: 484dcpmb3vazu Plan Hash: 2949544139

select *
from
 scott.emp where empno=:x


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          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          2          0           1

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
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=38 us cost=1 size=38 card=1)
         1          1          1   INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=19 us cost=0 size=0 card=1)(object id 87109)


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.01          0.01

3、各部分詳細分析

1)第一部分是SQL ID、Plan Hash和sql文本

SQL ID: 484dcpmb3vazu Plan Hash: 2949544139

select *
from
 scott.emp where empno=:x

2)第二部分是此次SQL運行時各項指標的統計信息的匯總

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          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          2          0           1

行名解釋

• parse   解析SQL語句部分

• execute SQL語句的執行執行部分，對于INSERT/UPDATE/DELETE語句，對就的是修改的行，對于SELECT語句標示返回的行數

• fetch   查詢的返回行數，只在select語句有效

列名解釋

• count   語句在解析、執行或FETCH階段的次數

• cpu     語句在解析、執行或FETCH階段所消耗的總CPU時間(秒)，如果TIMED_STATISTICS沒有打開則值為0

• elapsed 語句在解析、執行或FETCH階段所消耗的總時間(秒)，如果TIMED_STATISTICS沒有打開則值為0

• disk    語句在解析、執行或FETCH階段對在磁盤上的數據文件的總物理讀數量

• query   語句在解析、執行或FETCH階段對buffer一致讀模式的次數，通常對應查詢語句

• current 語句在解析、執行或FETCH階段對buffer當前讀模式的次數，對應INSERT/UPDATE/DELETE語句

• rows    語句總共產生的行數，不包含SQL中子查詢產生的行數

3)第三部分Library Cache information

列出了語句在解析和執行階段時library cache miss的次數，如果語句沒有library cache miss,則tkprof不顯示。還列出了優化器模式等信息

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1

4)第四部分為Row source plan

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=38 us cost=1 size=38 card=1)
         1          1          1   INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=19 us cost=0 size=0 card=1)(object id 87109)

• cr   一致讀次數

• pr   物理讀次數

• pw   物理寫次數

• time 消耗的時間(微秒)

• cost 這個操作的消耗

• size 預估的返回大小(bytes)

• card 預估的cardinality

第五部分：語句執行的等待事件信息

包括各個等待事件的等待次數和等待時間。

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.01          0.01

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

參考文檔：https://blogs.oracle.com/askmaclean/entry/maclean%E6%95%99%E4%BD%A0%E8%AF%BBoracle_10046_sql_trace

MOS文檔：TKProf Interpretation (9i and above) (文檔 ID 760786.1)

Interpreting Raw SQL_TRACE output (文檔 ID 39817.1)