之前简单的写了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的语法：
|
1
2
3
|
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后的示例
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
|
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文本
|
1
2
3
4
5
|
SQL ID: 484dcpmb3vazu Plan Hash: 2949544139
select
*
from
scott.emp where empno=:x
|
2)第二部分是此次SQL运行时各项指标的统计信息的汇总
|
1
2
3
4
5
6
7
|
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不显示。还列出了优化器模式等信息
|
1
2
3
4
|
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
|
1
2
3
4
|
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
第五部分：语句执行的等待事件信息
包括各个等待事件的等待次数和等待时间。
|
1
2
3
4
5
|
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)
本文转自hbxztc 51CTO博客，原文链接：http://blog.51cto.com/hbxztc/1898753，如需转载请自行联系原作者
