解释TKPROF输出
分析的输出文件根据以下参数生成：
tkprof DBM11203_ora_28030.trc
DBM11203_ora_28030.txt
sort=prsela,exeela,fchela print=4
explain=chris/ian aggregate=no
输出文件的头部信息大部分是静态的。然而，这里面也有有用的信息：跟踪文件名、生成输出文件时参数sort的值以及定位跟踪会话的一行信息。最后这条信息只有在指定了参数aggregate=no时才会显示。请注意，当跟踪文件包含多个会话并且指定参数aggregate=no时，头部信息里会反复使用分隔符来区别SQL语句和其他会话。
TKPROF:Release 11.2.0.3.0 - Development on
Fri Nov 3023:45:572012
Copyright(c)1982, 2011, Oracle
and/or its affiliates. All rights
reserved.
Trace file: DBM11203_ora_28030.trc
Sort options: prsela exeela fchela
********************************************************************************
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
*** SESSION ID:(156.29)2012-11-30
23:21:45.691
任何连接数据库或者生成执行计划时的出错信息都会写在头部信息之后。
头部信息之后就是每条SQL语句的信息：SQL语句的文本、执行统计、解析信息、执行计划以及等待事件。仅当执行计划和等待事件存储在跟踪文件中时，才会报告执行计划和等待事件。请记住，在10.2版本中，只有当相关游标关闭后，才会将执行计划写入跟踪文件。这表明如果应用重用游标而不关闭它们，那么就不会将这些重用游标的执行计划写入跟踪文件。
SQL语句的文本在有些情况下是格式化后的。然而并不是所有情况下都能得到正确的显示格式。比如，在下面的例子中extract函数的关键字FROM就与SELECT语句的FROM子句混淆。请注意，SQLID只对11.1.0.6及以后的版本有效，执行计划的值仅对11.1.0.7及以后的版本有效。
执行统计会根据数据库调用的类型进行汇总并以表格形式显示。每一项性能指标如下所示。
Ø count: 数据库调用执行的次数。
Ø cpu: 花费在数据库调用上的CPU时间总和，单位秒。
Ø elapsed: 花费在数据库调用上的运行时间总和，单位秒。如果此值高于CPU时间，那么在执行统计下面的部分你会找到等待事件，那里有资源或同步点等待的信息。
Ø disk:代表物理读的块数。注意，这不是物理I/O数。如果这个值比逻辑读大(disk>query+current),就代表块涌进了临时表空间。这种情况下你可以看到至少读取了33017(71499-38474-8)个块。这需要稍后通过Row Source Operation的统计和等待事件来确认。
Ø query: 一致性逻辑读的块数。通常查询会用到这种逻辑读。
Ø current: 在当前模式下使用逻辑读读取的块数。通常INSERT、DELETE、MERGE和UPDATE语句修改块会产生此类逻辑读。
Ø rows:处理的行数。对于查询来说，这是获取的行数。对于INSERT、DELETE、MERGE和UPDATE来说这是受影响的行数。在这里10001次调用获取了1000000行是没有任何意义的。这表示平均来看每次调用获取了大约100行。注意这里的100是在PL/SQL里设置的预获取值。
接下来的几行是关于解析的基本概括信息。头两个值(Misses in library cache)代表在解析和执行调用期间的硬解析数。如果在执行调用期间没有硬解析，那么这行就不会显示。接下来是优化器模式和解析此SQL语句的用户ID。
请注意用户名(本例里是chris)只有指定了参数explain时才会显示。否则只会显示用户ID(这里是34)。
最后一条信息是递归深度。这条信息仅是为递归SQL语句提供的。直接由应用执行的SQL语句深度为0。深度n(本例是1)仅代表另一个深度为n-1的SQL语句执行了这个SQL。在这个例子中，深度为0的SQL语句是由SQL*Plus执行的PL/SQL块。
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34 (CHRIS)
(recursive depth: 1)
在解析的基本信息之后就是执行计划了。实际上，如果指定了参数explain,可能会看到两部分信息。
第一部分叫作Row
Saurce Operation,是由多个服务器进程写入跟踪文件的执行计划。
第二部分叫作Execution
Plan, 当指定参数explain后由TKPROF生成。由于它是后生成的，即使与第一部分不同也没关系。总之，如果你发现两部分不同，就以第一部分为准。
对于跟踪文件里的第一个执行计 划，两部分执行计划都会有执行计划里每步执行返回的行数(注意，不是处理的行数)。除此之外，11.2.0.2及更高的版本也提供了所有执行返回的平均行数和最大行数。执行计划本身的数量是由Number of plan statistics captured值提供的。
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ----------
---------------------------------------------------
1000000 1000000 1000000
SORT ORDER BY (cr=38474 pr=71499 pw=33035 time=11123996 us cost=216750
size=264000000 card=1000000)
1000000 1000000 1000000
TABLE ACCESS FULL T (cr=38474 pr=38463 pw=0 time=5674541 us cost=21
size=264000000 card=1000000)
Rows
Execution Plan
-------
---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1000000
SORT (ORDER BY)
1000000
TABLE ACCESS MODE: ANALYZED
(FULL) OF 'T' (TABLE)
对于每个row source
operation,还可能会提供以下运行时统计信息。
Ø cr是一致性逻辑读的块数。
Ø pr是物理读的块数。
Ø pw是物理写的块数。
Ø time是执行操作运行时间总和，单位微秒。请注意这里显示的值并不总是那么精确。因为为了降低开销，服务进程会使用采样来衡量。
Ø cost是操作的估计成本。这个值自11.1版本起开始启用。
Ø size是操作返回的预计数据大小(bytes)。这个值自11.1版本起开始启用。
Ø card是操作返回的预估行数。这个值自11.1版本起开始启用。
请注意，除了查询优化器的估值，其他的运行时统计信息都是累加出来的，它包含了child row source operation的值。例如，SORT ORDER BY命令从临时表空间读取了33036(71499-38463)个块。根据之前的执行信息(参见关于disk列部分的介绍),你应该能够估算出至少读取了33017个块。同时请注意，虽然在以前的版本中这些值只跟第一次查询有关，但从11.2.0.2版本开始它们变成了所有查询的平均值；在这种情况下就变得没有区别了，因为只有一次查询。
接下来的部分简要说明了SQL语句等待的等待事件。针对每种类型的等待事件，会提供以下值。
Ø Times Waited 是等待事件发生的次数。
Ø Max.Wait 是单个等待事件等待的最大时间，单位秒。
Ø Toal Waited 是等待事件的总等待时间，单位秒。
Elapsed times include waiting on following
events:
Event waited on Times Max. Wait
Total Waited
---------------------------------------- Waited
---------- ------------
db
file sequential read
2 0.00 0.00
db
file scattered read
530 0.06 2.79
direct path write temp 11002 0.00 0.51
direct path read temp 24015 0.00 2.41
理想情况下，所有等待事件的等待时间总和应该与执行统计信息里的运行时间与CPU时间的差值相等。这个差值称为未被计算的时间。
未被计算的时间
SQL跟踪会提供每次操作执行时数据库所花费时间的信息。理想情况下，计算应该非常精确。但是，几乎不能在跟踪文件里找到精确到秒级以下的准确信息。当真实的运行时间与跟踪文件里记录的时间不同时，就存在未被计算的时间。
unaccounted-for time = real elapsed time -
accounted for time
出现未被计算的时间最常见的原因如下。
Ø 最明显的是跟踪文件里缺少定时信息或等待事件。前者是因为初始化参数timed_statistics被设置成了FALSE。后者是因为启动SQL跟踪未包含级别8。在这两种情况下，未被计算的时间总是正值。正常情况下，恰当开启扩展的SQL跟踪能够避免这些问题。
Ø 通常来说，进程有三种状态：在CPU上运行、等待请求(例如，执行磁盘I/O操作)或在执行队列等待CPU资源。植入代码能够计算出前两种状态所花费的时间，但是对在执行队列等待多久却无能为力。因此，如果发生了CPU匮乏，那么未被计算的时间(始终为正值)可能会很长。基本上你可以通过两种方法避免这个问题：增加可用CPU的数量或者降低CPU使用率。
Ø 植入代码可做出精确的时间测量。然而，由于计算机系统中计时器的影响，每次测量会产生很小的量化误差。尤其是当有大量的测量时间时，这种量化误差造成的未被计算的时间会很明显。由于计时器自身的性质，量化误差可能会导致未被计算的时间为正值，也可能导致其为负值。遗憾的是，你对此无能为力。在实际应用中，这个问题与大量未被计算的时间无关，因为正误差往往会与负误差相抵消。
Ø 如果你排除了列出的这些方面，那么原因很可能是检测代码没有涵盖整个代码。例如，写入跟踪文件的时间就不会算在内。这通常不会是个问题。但如果跟踪文件写入一个性能差的设备或需要生成跟踪的信息量非常大，这时可能会产生大的开销。在这种情况下，未被计算的时间将始终为正值。为了避免这个问题，你应该把跟踪文件写入一个可以支撑正常吞吐量的设备上。在一些罕见的情况下，你或许会强制把跟踪文件放到RAM盘上。
由于等待事件的值已经高度聚合，这可以让你只需要知道你在等待哪类资源。比如，根据之前的信息，几乎所有的等待时间都花在了物理读上，但由于信息已经聚合，我们看不到具体信息，比如是从哪个数据文件读取的(原始跟踪文件里有这个信息)。实际上单块读的等待事件是db file sequential
read, 而多块读的等待事件是db
file scattered read。另外，涌入临时表空间的等待事件是direct path write temp和direct path read temp。
在分析等待事件时，关键是弄清楚与什么操作相关。幸运的是，即使等待事件种类有几百种，经常遇到的也就那么几种。在Oracle Database Reference手册的附录中有大部分等待事件的简介。
我们继续分析下一个SQL语句。由于这些信息结构与之前的一样，因此这里仅会注释输出文件中的新内容或本质的区别。
DECLARE
l_count INTEGER;
BEGIN
FOR
c IN (SELECT extract(YEAR FROM d), id, pad
FROM t
ORDER BY extract(YEAR FROM d), id)
LOOP
NULL;
END
LOOP;
FOR
i IN 1..10
LOOP
SELECT count(n) INTO l_count
FROM t
WHERE id < i*123;
END
LOOP;
END;
PL/SQL块的执行统计信息是有限的。它缺少物理读和逻辑读的信息，这是因为递归SQL语句(比如之前分析过的查询)使用的资源与父SQL语句无关。这表示你仅能看到SQL语句(或者PL/SQL块)本身使用的资源。
call
count cpu elapsed disk
query current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
1 0.00 0.00 0 0
0 0
Execute
1 0.44 0.40 0 0 0 1
Fetch
0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
2 0.45 0.41 0 0 0 1
由于PL/SQL块不是由数据库递归执行的，因此这里不会显示递归深度(递归深度为0)。同样，也不会显示执行计划。
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34 (CHRIS)
当网络层发送数据给客户端时(注意，通过网络发送数据的时间不会计算在内),数据库等待 SQL*Net message to client,而数据库等待客户端返回消息时等待SQL*Net message from
client。因此，对于每个由SQL*Net
层完成的往返，你都能看到一对等待事件。请注意，在低级别层实现的往返次数会有些不同。比如，在网络层(比如IP)由于较小的数据包而完成大量往返的情况并 不少见。
Elapsed times include waiting on following
events:
Event waited on Times Max. Wait
Total Waited
---------------------------------------- Waited
---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
接下来是第二个由PL/SQL块执行的SQL语句。结构信息与之前的一致。需要指出的是，这个查询被执行了10次。对于每次执行，跟踪文件都包含执行统计信息(启用了级别16的)。因此，plan statistics captured的值是10,三行数据中每列都包含了不同的值(122676和1229),并且行来源级别的运行时统计信息为平均值(比如，53的磁盘读除以10次执行，平均值为5)。
SQL ID: 7fjjjf0yvd05m Plan Hash: 4270555908
SELECT COUNT(N)
FROM
T
WHERE ID < :B1 *123
call
count cpu elapsed disk
query current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
1 0.00 0.00 0 0 0 0
Execute
10 0.00 0.00 0 0 0 0
Fetch
10 0.00 0.02 53 303 0 10
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
21 0.01 0.02 53 303 0 10
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34 (CHRIS)
(recursive depth: 1)
Number of plan statistics captured: 10
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ----------
---------------------------------------------------
1 1 1
SORT AGGREGATE (cr=30 pr=5 pw=0 time=2607 us)
122 676 1229
TABLE ACCESS BY INDEX ROWID T (cr=30 pr=5 pw=0 time=2045 us cost=8 size=1098
card=122)
122 676 1229
INDEX RANGE SCAN T_PK (cr=4 pr=0 pw=0 time=872 us cost=3 size=0 card=122)(object
id 20991)
Rows
Execution Plan
-------
---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 SORT (AGGREGATE)
122 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'T'
(TABLE)
122 INDEX MODE: ANALYZED (RANGE SCAN) OF 'T_PK' (INDEX
(UNIQUE)
)
Elapsed times include waiting on following
events:
Event waited on Times Max. Wait
Total Waited
---------------------------------------- Waited
---------- ------------
db
file sequential read
53 0.00 0.02
--------------------------------------------------------------------------------
为了获取被使用的对象信息(比如对象统计信息),数据库引擎递归执行最后的SQL语句。此外，查询优化器会使用此信息来计算出最有效率的执行计划。解析这条SQL的用户是SYS,因此你可以判断是由数据库引擎执行的这条SQL语句。根据递归深度为2,可以推断这条SQL语句需要解析深度为1的SQL,比如在输出文件中的第一个SQL语句。
SQL ID: 96g93hntrzjtr Plan Hash: 2239883476
select /*+ rule */ bucket_cnt, row_cnt,
cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call
count cpu elapsed disk
query current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
0 0.00 0.00 0
0 0 0
Execute
4 0.00 0.00 0 0 0 0
Fetch
4 0.00 0.01 5 12 0 4
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
8 0.00 0.01 5 12 0 4
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 2)
本例中由于表来源的信息没有记录在跟踪文件里，并且用户CHRIS没有这条SQL语句涉及的对象权限，因此没有显示执行计划。输出部分接下来是等待事件。
Elapsed times include waiting on following
events:
Event waited on Times Max. Wait
Total Waited
---------------------------------------- Waited
---------- ------------
db
file sequential read 5 0.00 0.01
在所有SQL语句的报告后，你可以看到执行统计信息、解析和等待事件的综合统计。这里唯一需要注意的就是非递归SQL从递归SQL里分离出来。
OVERALL TOTALS FOR ALL NON-RECURSIVE
STATEMENTS
call
count cpu elapsed disk
query current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
2 0.00 0.00 0 0 0 0
Execute
3 0.45 0.42 20 226 0 3
Fetch
0 0.00
0.00 0 0 0 0
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
5 0.45 0.42 20 226 0 3
Misses in library cache during parse: 2
Misses in library cache during execute: 1
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.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call
count cpu elapsed disk
query current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
2 0.00 0.00 0 0 0 0
Execute
29 0.00 0.00 0 0
0 0
Fetch
10037 6.50 11.97
71569 38832 8
1000028
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
10068 6.50 11.97
71569 38832 8
1000028
Misses in library cache during parse: 2
Misses in library cache during execute: 2
Elapsed times include waiting on following
events:
Event waited on Times Max. Wait
Total Waited
---------------------------------------- Waited
---------- ------------
db
file sequential read
72 0.00 0.04
db
file scattered read
530 0.06 2.79
direct path write temp 11002 0.00 0.51
direct path read temp 24015 0.00 2.41
接下来的几行是对当前会话的SQL数量进行概括，包括由数据库引擎递归执行的数量和EXPLIAN PLAN执行的次数：
5 user SQL statements in session.
13 internal SQL statements in
session.
18 SQL statements in session.
2 statements EXPLAINed in this session.
现在，输出文件已经包含了跟踪文件的所有信息。首先，你能看到跟踪文件名、其版本和用于分析的参数sort的值。接着是所有会话数和SQL语句。在这个例子中，跟踪文件里少了14(18-4)行SQL语句是因为指定了参数print=4。同时也记录了执行EXPLAIN PLAN的表信息。
最后，是所有SQL语句的总运行时间(以秒为单位)。我个人更愿意在跟踪文件的头部看到最后这部分信息，因为每次我打开TKPROF的输出文件时，总是最先浏览最后部分。关键是要知道整个跟踪文件花费多少时间，否则你无法判断一个SQL语句对于总响应时间的影响程度。
Trace file: DBM11203_ora_28030.trc
Trace file compatibility: 11.1.0.7
Sort options: prsela exeela
fchela
1 session in tracefile.
5 user SQL statements in trace file.
13 internal SQL statements in
trace file.
18 SQL statements in trace file.
18 unique SQL statements in trace
file.
2 SQL statements EXPLAINed using
schema:
CHRIS.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
46125 lines in trace file.
12 elapsed seconds in trace file.
