之前简单的写了10046事件介绍的文章http://www.jb51.cc/article/p-xoxjiolz-xe.html，当然收集10046 trace不是最终的目的，能够读懂并且通过分析10046 trace进而分析相应sql的性能问题才是10046 trace真正发挥作用的地方。但是10046事件所产生的原始trace文件习惯称之为裸trace文件(raw trace)，Oracle记录在裸trace文件中的内容一眼看上去并不是那么观，也不是那么容易看懂。为了�trace文件能够以一种更直观、更容易懂的方式展现出来，Oracle提供了tkprof命令，这个命令是Oracle自带的，可以用它来翻译�trace文件。

1、tkprof的语法：

tkproffilename1filename2[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后的示例

sqlID:484dcpmb3vazuPlanHash:2949544139

select*
from
scott.empwhereempno=:x


callcountcpuelapseddiskquerycurrentrows
-----------------------------------------------------------------------
Parse10.000.000000
Execute10.000.000000
Fetch20.000.000201
-----------------------------------------------------------------------
total40.000.000201

Missesinlibrarycacheduringparse:1
Optimizermode:ALL_ROWS
Parsinguserid:SYS
Numberofplanstatisticscaptured:1

Rows(1st)Rows(avg)Rows(max)RowSourceOperation
---------------------------------------------------------------------------------
111TABLEACCESSBYINDEXROWIDEMP(cr=2pr=0pw=0time=38uscost=1size=38card=1)
111INDEXUNIQUESCANPK_EMP(cr=1pr=0pw=0time=19uscost=0size=0card=1)(objectid87109)


Elapsedtimesincludewaitingonfollowingevents:
EventwaitedonTimesMax.WaitTotalWaited
----------------------------------------Waited----------------------
sql*Netmessagetoclient20.000.00
sql*Netmessagefromclient20.010.01

3、各部分详细分析

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

sqlID:484dcpmb3vazuPlanHash:2949544139

select*
from
scott.empwhereempno=:x

2)第二部分是此次sql运行时各项指标的统计信息的汇总

callcountcpuelapseddiskquerycurrentrows
-----------------------------------------------------------------------
Parse10.000.000000
Execute10.000.000000
Fetch20.000.000201
-----------------------------------------------------------------------
total40.000.000201

行名解释

• 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不显示。还列出了优化器模式等信息

Missesinlibrarycacheduringparse:1
Optimizermode:ALL_ROWS
Parsinguserid:SYS
Numberofplanstatisticscaptured:1

4)第四部分为Row source plan

Rows(1st)Rows(avg)Rows(max)RowSourceOperation
---------------------------------------------------------------------------------
111TABLEACCESSBYINDEXROWIDEMP(cr=2pr=0pw=0time=38uscost=1size=38card=1)
111INDEXUNIQUESCANPK_EMP(cr=1pr=0pw=0time=19uscost=0size=0card=1)(objectid87109)

• cr 一致读次数

• pr 物理读次数

• pw 物理写次数

• time 消耗的时间(微秒)

• cost 这个操作的消耗

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

• card 预估的cardinality

第五部分：语句执行的等待事件信息

包括各个等待事件的等待次数和等待时间。

Elapsedtimesincludewaitingonfollowingevents:
EventwaitedonTimesMax.WaitTotalWaited
----------------------------------------Waited----------------------
sql*Netmessagetoclient20.000.00
sql*Netmessagefromclient20.010.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)