tkprof的格式化输出文件主要包含：

(1)header

(2)body

(3)summary


1、header：

主要包括一些描述信息，如TKPROF的版本、运行时间，各个统计项的描述。如：

TKPROF: Release 8.1.7.0.0 - Production on 星期四 6月 30 13:10:59 2005

（c） Copyright 2000 Oracle Corporation. All rights reserved.

Trace file: D:\oracle\admin\xyj\udump\ORA01720.TRC

Sort options: default

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

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

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


2、body：

是我们主要关心的地方，有我们感兴趣的信息。如sql语句、sql语句的统计信息、sql语句的执行计划等。如

select *

from

emp

call count cpu elapsed disk query current rows

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

Parse 3 0.00 0.00 1 0 1 0

Execute 3 0.00 0.00 0 0 0 0

Fetch 6 0.00 0.00 1 6 12 36

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

total 12 0.00 0.00 2 6 13 36

Misses in library cache during parse: 1

Optimizer goal: CHOOSE

Parsing user id: 19 （SCOTT）

Rows Row Source Operation

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

12 TABLE ACCESS FULL EMP

Rows Execution Plan

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

0 SELECT STATEMENT GOAL: CHOOSE

12 TABLE ACCESS （FULL） OF 'EMP'

DELETE FROM RM$HASH_ELMS

call count cpu elapsed disk query current rows

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

Parse 2 0.00 0.00 0 0 0 0

Execute 29 12.04 12.61 6786 6853 108 19

Fetch 0 0.00 0.00 0 0 0 0

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

total 31 12.04 12.61 6786 6853 108 19

Misses in library cache during parse: 0

Optimizer hint: CHOOSE

Parsing user id: 9 （DES12A） （recursive depth: 3）

Rows Execution Plan

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

0 DELETE STATEMENT HINT: CHOOSE

16 TABLE ACCESS （FULL） OF 'RM$HASH_ELMS'


3、summary：

对所有的sql语句各个执行阶段的统计数据的汇总：

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS - - 标明是用户发出的sql语句的统计数据的汇总

call count cpu elapsed disk query current rows

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

Parse 7 0.00 0.00 2 201 2 0

Execute 7 0.00 0.00 1 2 7 1

Fetch 10 0.00 0.00 2 67 16 52

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

total 24 0.00 0.00 5 270 25 53

Misses in library cache during parse: 5

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS - - 标明是系统发出的sql语句的统计数据的汇总

call count cpu elapsed disk query current rows

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

Parse 75 0.00 0.00 2 3 2 0

Execute 81 0.00 0.00 1 1 5 1

Fetch 153 0.00 0.00 21 355 0 110

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

total 309 0.00 0.00 24 359 7 111

Misses in library cache during parse: 29

8 user SQL statements in session.

74 internal SQL statements in session.

82 SQL statements in session.

5 statements EXPLAINed in this session.

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

Trace file: D:\oracle\admin\xyj\udump\ORA01720.TRC

Trace file compatibility: 8.00.04

Sort options: default

1 session in tracefile.

8 user SQL statements in trace file.

74 internal SQL statements in trace file.

82 SQL statements in trace file.

34 unique SQL statements in trace file.

5 SQL statements EXPLAINed using schema:

SCOTT.prof$plan_table

Default table was used.

Table was created.

Table was dropped.

825 lines in trace file.


4、现只对body中的每部分作出详细说明：

1） sql语句的统计信息

我们把select语句的执行过程分成3个阶段（分析 执行 取结果），把DML语句的执行分成2个阶段（分析 执行）。格式化的输出文件中列出了sql语句执行的每一阶段所耗费资源统计信息，对于这些信息，是以行列的模式给出的。每一行代表每个sql执行中的具体某一阶段所耗费的相应资源。这样通过分析每个阶段耗费的资源，可以知道哪个sql有问题，并进一步知道该sql执行过程中哪一阶段出现了问题，从而快速定位问题，进而迅速解决问题。

下面对每个列进行说明：

call：表示sql语句执行的每个阶段，每个sql语句的活动被分成以下3部分：

Parse：语句被解析的次数，主要是生成执行计划。包含hard parse与soft parse。需要做的工作：权限检查，表、列、引用的表的存在性检查；比较执行计划，选出最好的一个等等。

Execute：真正执行语句的时间，对于DML语句，在此阶段中修改数据；对于select语句，这步只是标识出查询出的行。

Fetch：只对select语句有效，DML语句的执行并没有该阶段，其它列的值都是与sql执行三个阶段中所耗费的资源的统计值

Count：一个语句被parsed、executed、fetched的次数

Cpu：执行这个语句的每个阶段耗费的cpu时间

Elapsed：执行这个语句的每个阶段耗费的总时间（包括上面的cpu时间与其它时间，如读数据）

Disk：每个阶段读硬盘的次数（有可能从file system buffer中取得数据）。对于该参数，我们希望该值越小越好，如果该值很大，该sql需要调整，建立相关索引或看是否正确的使用了索引。

Query：每个阶段以consistent mode 方式从数据库buffer中查询的buffers数。对于查询，其buffer一般都是以consistent mode模式被读取

Current：每个阶段以current mode方式从数据库buffer中查询的buffers数。对于DML语句，需要的buffer是以current mode模式被读取的。QUERY + CURRENT 的和是该sql语句总的存取的buffer数目。

Rows：这个sql语句最后处理的行数，不包括子查询中查询出来的行数。对于select语句，该值产生于fetch阶段；对于dml该值产生于execute阶段。

因为统计耗费的时间时，最小的计量单位为0.01秒，所以如果得到一个阶段中耗费的时间为0，并不表示这个阶段没有耗费时间，而是极可能说明这个阶段耗费的时间小于0.01秒，小于计量单位，数据库无法计时，只要以0.00表示


2） 与执行计划有关的内容

Misses in library cache during parse: 1 -- 说明hard parse的次数

Optimizer goal: CHOOSE -- 采用的优化器

Parsing user id: 19 （SCOTT） -- 那个用户执行的该sql

Rows Row Source Operation

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

12 TABLE ACCESS FULL EMP

Rows Execution Plan -- 下面是真正的执行计划

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

0 SELECT STATEMENT GOAL: CHOOSE

12 TABLE ACCESS （FULL） OF 'EMP'


Misses in library cache during parse: 这个统计值是一个比较重要的指标，如果该值与该语句的parse统计值基本相等，并且该值比较大，而且该sql的parse阶段耗费的资源比较多，则说明你的语句应该采用bind variable模式。

执行计划部分也比较重要，它能看出查询是否用了索引，和各种关联操作所采用的方法。


建议用autotrace进行跟踪而不是用上面方法进行跟踪的原因：

虽然上面的方法给出了sql语句的执行计划、统计数据等信息，但是因为tkprof的格式化输出不给出详尽的costs与statistics信息，这使我们在利用格式化输出判断系统到底是使用基于代价的优化方法还是基于规则的优化方法时，感到很迷茫，我们不能明确的知道到底系统在使用那种优化器。

但是仅仅因为这个原因就使我们放弃上面跟踪方法而该用autotrace功能是不够的，因为：

1） 到底系统是使用基于规则的还是基于代价的优化器我们可以借助与其它信息来识别，而且从10G以后，oracle就宣布不再使用基于规则的优化器了。

2） 上面的跟踪办法能实现autotrace不能完成的功能，因为autotrace只能跟踪本会话，而不能跟踪其它会话，这样假如有一个正在运行的程序出现了性能问题，我们就不能使用autrace去跟踪sql的执行情况。


oracle视频教程请关注:http://u.youku.com/user_video/id_UMzAzMjkxMjE2.html