oracle 工具：tkprof

1 定义

用于分析oracle跟踪文件并且可按需产生一个更加清晰合理的输出结果的可执行工具

2 首选项

F:\>tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
    userid  userid of user that parsed the cursor

注释：
① fchela这是个比较有用的sort选项，在生成的.prf文件将把最消耗时间的sql放在最前面显示
② sys=no 以sys身份执行的sql不会被显示，增加可读性

3 tkprof输出文件中各列的含义

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

注释：
㈠ call：
每次sql的处理都分成3个部分
① parse：将sql语句转成执行计划，包括检查权限、表及其关联对象是否存在等
② execute：由sql引擎执行，因事务类型不同而异
③ fetch：这步只有select语句被执行，buffer cache是主战场
㈡ count：
这条sql被parse、execute和fetch的次数
㈢ cpu：该sql语句所消耗的cpu的时间（单位：s）
㈣ elapsed：该sql语句在各个阶段的执行时间
㈤ disk：
从磁盘上的数据文件中物理读取的块的数量
㈥ query：
在一致性读的模式下，各阶段所获得的buffer的数量。一致性模式下，buffer是用于给一个长查询提供一致性
读的快照
㈦ current：
在当前读的模式下，各阶段所获得的buffer的数量。
㈧ rows：
所有的sql返回的记录数目，但不包括子查询返回的记录。
对于select语句，返回是在fetch这步
对于DML语句，返回是在execute这步

4 tkprof的使用步骤

⑴ 在实例级别上设置timed_statistic=true
SQL> show parameter timed_statistic

NAME_COL_PLUS_SHOW_P TYPE VALUE_COL_PLUS_SHOW_
-------------------- ---------------------- --------------------
timed_statistics boolean TRUE
⑵ 使用各种工具得到想要查看session的trc文件
⑶ udump路径找到生成的trc文件
⑷ 对trc文件进行tkprof分析
tkprof tracefile outfile [options]
注意：这条语句后面没有分号结尾！！

5案例

18:32:55 hr@ORCL (^ω^) alter session set events '10046 trace name context forever,level 12';

会话已更改。

18:34:00 hr@ORCL (^ω^) select count(*) from t;

  COUNT(*)
----------
         2
18:34:00 hr@ORCL (^ω^) update t1 set tname='think high' where id=1;

已更新 1 行。
18:34:30 hr@ORCL (^ω^) alter session set events '10046 trace name context off';

会话已更改。

18:34:55 hr@ORCL (^ω^) exit

D:\oracle\product\10.2.0\admin\orcl\udump>tkprof orcl_ora_6004.trc C:\Users\Administrator\tkprof_starting.txt sys=no waits=yes sort=fche

TKPROF: Release 10.2.0.1.0 - Production on 星期日 9月 23 19:19:13 2012

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

这个tkprof文件最后的一部分如下：

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       11      0.03       0.16          0          0          0           0
Execute     41      0.07       0.22          0          0          0           0
Fetch       48      0.03       0.12          3        118          0          50
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      100      0.14       0.51          3        118          0          50

Misses in library cache during parse: 11
Misses in library cache during execute: 11

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         3        0.02          0.05

    3  user  SQL statements in session.
   41  internal SQL statements in session.
   44  SQL statements in session.
********************************************************************************
Trace file: orcl_ora_6004.trc
Trace file compatibility: 10.01.00
Sort options: fchela  
       1  session in tracefile.
       3  user  SQL statements in trace file.
      41  internal SQL statements in trace file.
      44  SQL statements in trace file.
      14  unique SQL statements in trace file.
     902  lines in trace file.
      55  elapsed seconds in trace file.

注释：
① 这个session共有44条sql语句在里面，对于递归的语句一共分析了41次
② 计算hit ratio
logical reads=consistent gets+ db block gets
consistent gets=query列的execute+query列的fetch
db block gets=current列的execute+current列的fetch
因此，logical reads=118+0+0+0=118
physical reads=disk列，即：3
所以，hit ratio=L/（L+P)=97.5%
③ 还有一对参数非常重要，fetch的次数以及取得的记录的行数，一般来说，以尽可能少的fetch来取得尽可能多的记录数
，也就是，fetch的值要远远小于取得的记录数才好。从上面这个例子可知，fetch了48，rows 50，这表明
有些记录是通过好几次的fetch才得到的。这个session的有些sql是需要优化的。
④ 从query列的parse可以看出从row cache里读取的数据

这个tkprof文件中两个sql语句摘入如下：

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

select count(*) 
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.06          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.01          6          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.08          6          7          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=7 pr=6 pw=0 time=15493 us)
      2   TABLE ACCESS FULL T (cr=7 pr=6 pw=0 time=15449 us)


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
  db file sequential read                         1        0.01          0.01
  db file scattered read                          1        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00

注释：
从上面的输出可以看到，这条语句访问了7个块来找到需要select的记录，返回1条记录。
这个查询parse了1次，而且是hard parse 1次。

select语句主要看fetch这一行

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

update t1 set tname='think high' 
where
 id=1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.03          0          5          2           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.03          0          1          1           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  UPDATE  T1 (cr=1 pr=0 pw=0 time=31186 us)
      1   INDEX UNIQUE SCAN INDEX_T1 (cr=1 pr=0 pw=0 time=23 us)(object id 54498)


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

注释：
这条语句访问了5个block来找到需要的update的记录，在执行update的时候只访问了2个，一共更新了1条记录

DML语句主要看execute这一行