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

    之前簡單的寫了10046事件介紹的文章http://hbxztc.blog.51cto.com/1587495/1898624，當(dāng)然收集10046 trace不是最終的目的，能夠讀懂并且通過分析10046 trace進(jìn)而分析相應(yīng)sql的性能問題才是10046 trace真正發(fā)揮作用的地方。但是10046事件所產(chǎn)生的原始trace文件習(xí)慣稱之為裸trace文件(raw trace)，Oracle記錄在裸trace文件中的內(nèi)容一眼看上去并不是那么觀，也不是那么容易看懂。為了祼trace文件能夠以一種更直觀、更容易懂的方式展現(xiàn)出來，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

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

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

2、一個簡單sql對應(yīng)的trace經(jīng)過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、各部分詳細(xì)分析

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

SQL ID: 484dcpmb3vazu Plan Hash: 2949544139

select *
from
 scott.emp where empno=:x

2)第二部分是此次SQL運行時各項指標(biāo)的統(tǒng)計信息的匯總

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語句的執(zhí)行執(zhí)行部分，對于INSERT/UPDATE/DELETE語句，對就的是修改的行，對于SELECT語句標(biāo)示返回的行數(shù)

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

列名解釋

• count   語句在解析、執(zhí)行或FETCH階段的次數(shù)

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

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

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

• query   語句在解析、執(zhí)行或FETCH階段對buffer一致讀模式的次數(shù)，通常對應(yīng)查詢語句

• current 語句在解析、執(zhí)行或FETCH階段對buffer當(dāng)前讀模式的次數(shù)，對應(yīng)INSERT/UPDATE/DELETE語句

• rows    語句總共產(chǎn)生的行數(shù)，不包含SQL中子查詢產(chǎn)生的行數(shù)

3)第三部分Library Cache information

列出了語句在解析和執(zhí)行階段時library cache miss的次數(shù)，如果語句沒有l(wèi)ibrary cache miss,則tkprof不顯示。還列出了優(yōu)化器模式等信息

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   一致讀次數(shù)

• pr   物理讀次數(shù)

• pw   物理寫次數(shù)

• time 消耗的時間(微秒)

• cost 這個操作的消耗

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

• card 預(yù)估的cardinality

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

包括各個等待事件的等待次數(shù)和等待時間。

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)