tkprof分析trace文件

一. TKPROF 命令语法：
TKPROF  filename1, filename2 [ SORT  = [ opion][,option] ]
  [  PRINT = integer ]
  [ AGGREGATE  = [ YES | NO ] ]
  [ INSERT = filename3 ]
  [ SYS = [ YES | NO ]  ]
  [  [ TABLE = schema.table ] | [ EXPLAIN = user/password ]  ]
  [  RECORD = filename ]

PRINT        只列出输出文件的第一个integer 的SQL语句。默认为所有的SQL语句。
AGGREGATE    如果= NO ，则不对多个相同的SQL进行汇总。
INSERT       SQL 语句的一种，用于将跟踪文件的统计信息存储到数据库中。在TKPROF创建脚本后，在将结果输入到数据库中。
SYS         禁止或启用 将SYS用户所发布的SQL语句列表到输出文件中。
TABLE       在输出到输出文件前，用于存放临时表的用户名和表名。
EXPLAIN     对每条SQL 语句确定其执行规划。并将执行规划写到输出文件中。

其中比较有用的一个排序选项是fchela，即按照elapsed time fetching来对分析的结果排序（记住要设置初始化参数timed_statistics=true），生成的文件将把最消耗时间的sql放在最前面显示。另外一个有用的参数就是sys，这个参数设置为no可以阻止所有以sys用户执行的sql被显示出来，这样可以减少分析出来的文件的复杂度，便于查看。

 

tkprof 文件含义：

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数。Buffers are often

　　对于DML语句，需要的buffer是以current mode模式被读取的。

　　QUERY + CURRENT 的和是该sql语句总的存取的buffer数目

　　ROWS

　　这个sql语句最后处理的行数，不包括子查询中查询出来的行数。

　　对于select语句，该值产生于fetch阶段;对于dml该值产生于execute阶段。

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

 

先从os上利用top命令找到当前占用cpu资源最高的一个进程的PID号：14483
然后在数据库中根据PID号找到相应的sid号和serial#：
SQL> select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and p.spid='14483';
       SID    SERIAL#
---------- ----------
       101      25695

使用dbms_system.set_sql_trace_in_session包来对这个session进行trace：
SQL> exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(101,25695,true);
PL/SQL procedure successfully completed.

到user_dump_dest定义的路径下查找刚刚最近生成的trace文件，可以根据时间来排序，找最近的trace文件，也可以根据SID_ORA_SPID.TRC的规则，即ORCL_ORA_14483.TRC找到TRACE文件。

接着使用tkprof工具对此trace文件进行格式化分析，生成分析后的trace文件。
$tkprof orcl_ora_14483.trc allan.txt explain=system/manager aggregate=yes sys=no waits=yes sort=fchela

TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

 

下面以一个具体的例子的数据说明如何利用格式化的输出文件进行sql的调整：

　　第一步： - 现看格式化输出文件最后部分，即汇总部分

　　===========================================================

　　OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

　　| call | count | cpu | elapsed | disk | query | current | rows |

　　|--------- |------- |------ |--------- |--------- |-------- |--------- |-------- |

　　| Parse | [A] 7 | 1.87 | 4.53 | 385 | [G] 553 | 22 | 0 |

　　| Execute | [E] 7 | 0.03 | 0.11 | [P] 0 | [C] 0 | [D] 0 | [F] 0 |

　　| Fetch | [E] 6 | 1.39 | 4.21 | [P] 182 | [C] 820 | [D] 3 | [F] 20 |

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

　　Misses in library cache during parse: 5

　　Misses in library cache during execute: 1

　　8 user SQL statements in session.

　　12 internal SQL statements in session.

　　[B] 54 SQL statements in session.

　　3 statements EXPLAINed in this session.

　　(1). 通过比较 [A] 与 [B]，我们可以发现是否有过量的parsing现象。在上面的例子中，我们可以看到在session中执行了54个语句，但是只有7次parses，所以这是比较正常的，没有过量的parse现象。

　　(2). 利用 [P], [C] & [D] 来决定数据库高速缓存的命中率问题

　　Hit Ratio is logical reads/physical reads:

　　Logical Reads = Consistent Gets + DB Block Gets

　　Logical Reads = query + current

　　Logical Reads = Sum[C] + Sum[D]

　　Logical Reads = 0+820 + 0+3

　　Logical Reads = 820 + 3

　　Logical Reads = 823

　　Hit Ratio = 1 - (Physical Reads / Logical Reads)

　　Hit Ratio = 1 - (Sum[P] / Logical Reads)

　　Hit Ratio = 1 - (128 / 823)

　　Hit Ratio = 1 - (0.16)

　　Hit Ratio = 0.84 or 84%

　　(3). 我们希望fetch的次数要比rows小，即一次fetch可以取多行数据(array fetching)，

　　可以我们可以更高效的取得查询数据。

　　这可以通过比较[E]与[F].

　　[E] = 6 = Number of Fetches

　　[F] = 20 = Number of Rows

　　从上面的信息中我们可以看到，6次fetch总共取了20行数据，结果不是很坏。如果使用了经过良好配置arrayfetching，则可以用更少的fetch次数取到同样数量的数据，性能会更好。

　　(4). [G] 表示为了对语句进行分析，读数据字典告诉缓存的次数

　　- 这个参数对性能的影响不大，一般不用关心。而且这个统计值一般不是我们可以控制的。

　　第二步 – 检查耗费大量资源的语句

　　===============================================

　　update ...

　　where ...

　　| call | count | cpu | elapsed | disk | query | current | rows |

　　|--------- |------- |----- |--------- |------ |-------- |--------- |-------- |

　　| Parse | 1 | 7 | 122 | 0 | 0 | 0 | 0 |

　　| Execute | 1 | 75 | 461 | 5 | [H] 297 | [I] 3 | [J] 1 |

　　| Fetch | 0 | 0 | 0 | 0 | 0 | 0 | 0 |

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

　　[H] 表明需要访问297个数据块才能找到我们需要修改的数据。

　　[I] 表明我们的修改操作才修改3个数据块中的数据

　　[J] 表明我们只修改了一行数据(其它数据块的修改应为undo、redo信息)

　　为了修改一行数据而要搜寻297个数据块。

　　考虑是否需要在查许的列上建一个索引!

 

　　第三步 – 查看是否有过量的parse现象

　　==============================

　　select ...

　　| call | count | cpu | elapsed | disk | query | current | rows |

　　|--------- |------ -|--------- |--------- |----- -|------- -|-------- -|------ -|

　　| Parse | [M] 2 | [N] 221 | 329 | 0 | 45 | 0 | 0 |

　　| Execute | [O] 3 | [P] 9 | 17 | 0 | 0 | 0 | 0 |

　　| Fetch | 3 | 6 | 8 | 0 | [L] 4 | 0 | [K] 1 |

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

　　Misses in library cache during parse: 2 [Q]

　　[K] 表明这个查询只返回一行数据

　　[L] 表明我们需要fetch 4次才能得到数据，这是正常的，因为需要额外的fetch操作以便检查是否fetch到cursor的最后，当然还可能有其它fetch开销。

　　[M] 表明我们进行了两次parse(包含hard parse 与soft parse) – 这是我们不想看到的，

　　特别是当parse阶段操作耗费cpu资源比execute阶段耗费的cpu资源([O] & [P])

　　多得多得时候。 [Q] 表明这两个parse操作都是hard parse。如果[Q]的值为1，

　　这这个语句有一个hard parse，然后跟着一个soft parse(仅仅从库缓存中得到

　　上次分析的信息，比hard parse要高效的多)。

　　对上面的例子来说，结果并不是特别的坏，因为该语句只执行2次，然而如果对于频繁执行的sql来说，如果几乎每次执行都需要hard parse，则结果就会变的很坏，此时我们说该语句有过量的parse现象(excessive parsing)。