简单分析tkprof输出文件的内容

[oracle@rhf trace]$ tkprof orcl_ora_29583_rtrace.trc rhf2.prf explain=system/oracle sort=exeela,prsela,fchela

[oracle@rhf trace]$ ls -l rhf2.prf

-rw-r--r-- 1 oracle oinstall 49906 Aug 30 16:00 rhf2.prf

采用的上篇文章中的tkprof输出的文件rhf2.prf，因为仅仅是测试文件，所以这里只对文件中的关键部分进行描述。

1、头部信息

Trace file: orcl_ora_29583_rtrace.trc -- 头部显示追踪文件的名称

Sort options: exeela prsela fchela -- sort选项

********************************************************************************

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

********************************************************************************

头部显示追踪文件的名称，sort选项，还有输出文件中所使用的术语的描述。

2、sql执行的统计信息

tkprof列出追踪文件中每一个sql语句的执行统计信息。这些执行统计信息包括了三个步骤：解析、执行和获取。如下所示：

sql ID: 9a8v45jk7xhvx Plan Hash: 1250653294

select count(1)

from

dba_objects

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 1 0.01 0.02 0 0 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.17 0.38 940 945 0 1

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 4 0.19 0.40 940 945 0 1

以下对执行统计信息的含义：

count：数据库解析、执行和获取这条sql语句的次数。

cpu ：解析、执行、获取阶段阶段分别耗费的cpu时间。

elapsed：解析、执行、获取阶段所耗费的总运行是时间。

disk : 解析、执行、获取阶段所读取的物理数据块数。

query ：（一个select语句的）解析、执行、获取阶段以一致模式从缓冲区高速缓存中进行逻辑读取的数据块数目。

current：在current模式下以一致模式从缓冲区高速缓存中进行逻辑读取的数据块数目（对于insert、delete、update、merge语句）。

rows ：获取到的查询/插入/删除/更新的行数。

3、行源运算

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 SORT AGGREGATE (cr=945 pr=940 pw=0 time=384244 us)

75541 75541 75541 VIEW DBA_OBJECTS (cr=945 pr=940 pw=0 time=698919 us cost=264 size=0 card=75533)

75541 75541 75541 UNION-ALL (cr=945 pr=940 pw=0 time=614174 us)

75541 75541 75541 FILTER (cr=944 pr=940 pw=0 time=511914 us)

75541 75541 75541 HASH JOIN (cr=944 pr=940 pw=0 time=382942 us cost=263 size=8232988 card=75532)

95 95 95 INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=111 us cost=1 size=380 card=95)(object id 47)

75541 75541 75541 HASH JOIN (cr=943 pr=940 pw=0 time=251050 us cost=262 size=7930860 card=75532)

95 95 95 INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=200 us cost=1 size=2090 card=95)(object id 47)

75541 75541 75541 TABLE ACCESS FULL OBJ$ (cr=942 pr=940 pw=0 time=116564 us cost=260 size=6269156 card=75532)

0 0 0 nesTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=2 size=29 card=1)

0 0 0 INDEX SKIP SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)(object id 47)

0 0 0 INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=9 card=1)(object id 39)

0 0 0 nesTED LOOPS (cr=1 pr=0 pw=0 time=37 us cost=1 size=17 card=1)

0 0 0 INDEX FULL SCAN I_LINK1 (cr=1 pr=0 pw=0 time=34 us cost=0 size=13 card=1)(object id 138)

0 0 0 INDEX RANGE SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=4 card=1)(object id 47)

这部分显示 解析过程中sql在数据库高速缓冲中未命中的次数，当前的优化模式，以及查询的行源运算。行源运算显示数据库为每种运算，如关联或者全表扫描，所处理的数据的行数。

库高速缓冲中未命中的次数：在解析过程中所进行的硬解析和自行数据库调用的次数。

Row Source Operation：输出包括了每一个行源运算的各种统计信息。

cr : 在一致性模式下一次逻辑读取所获取的数据块数。

pr : 一次物理磁盘读取的数据块数。

pw: 一次物理磁盘写入中写入到磁盘的数据块数。

time：处理运算所花费的总时间（单位为毫秒）。

cost：估算的运算成本。

size：估算的运算返回的数据量（字节）。

card：估算的运算返回的数据行数。

4、执行计划

如果提交tkprof命令时指定了explain参数，会发现每一个sql语句都显示了执行计划。

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

direct path read 42 0.03 0.21

sql*Net message from client 2 29.94 29.94

********************************************************************************

只有在tkprof命令中指定了wait参数的值为true时，才会看到等待事件部分的内容。

注意：tkprof输出并不会显示任何绑定变量信息。同时不会显示队列锁引起的等待信息。