TKPROF 工具

转自david的博客：原文转：http://blog.csdn.net/tianlesoftware/article/details/5632003

Tkprof是一个用于分析Oracle跟踪文件并且产生一个更加清晰合理的输出结果的可执行工具。如果一个系统的执行效率比较低，一个比较好的方法是通过跟踪用户的会话并且使用Tkprof工具使用排序功能格式化输出，从而找出有问题的SQL语句。

一. 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 ]

相关说明：
filename1  指定的输入文件，可以是多个文件联起来。
Filename2  格式化输出文件。
SORT     在输出到输出文件前，先进程排序。如果省去，则按照实际使用的顺序输出到文件中。排序选项有以下多种：
  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

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语句的处理都分成三个部分
Parse：这步将SQL语句转换成执行计划，包括检查是否有正确的授权和所需要用到的表、列以及其他引用到的对象是否存在。
Execute：这步是真正的由Oracle来执行语句。对于insert、update、delete操作，这步会修改数据，对于select操作，这步就只是确定选择的记录。
Fetch：返回查询语句中所获得的记录，这步只有select语句会被执行。
COUNT:这个语句被parse、execute、fetch的次数。
CPU：这个语句对于所有的parse、execute、fetch所消耗的cpu的时间，以秒为单位。
ELAPSED：这个语句所有消耗在parse、execute、fetch的总的时间。
DISK：从磁盘上的数据文件中物理读取的块的数量。一般来说更想知道的是正在从缓存中读取的数据而不是从磁盘上读取的数据。
QUERY：在一致性读模式下，所有parse、execute、fetch所获得的buffer的数量。一致性模式的buffer是用于给一个长时间运行的事务提供一个一致性读的快照，缓存实际上在头部存储了状态。
CURRENT：在current模式下所获得的buffer的数量。一般在current模式下执行insert、update、delete操作都会获取buffer。在current模式下如果在高速缓存区发现有新的缓存足够给当前的事务使用，则这些buffer都会被读入了缓存区中。
ROWS: 所有SQL语句返回的记录数目，但是不包括子查询中返回的记录数目。对于select语句，返回记录是在fetch这步，对于insert、update、delete操作，返回记录则是在execute这步。

三. Tkprof的使用步骤基本上遵循以下几步：
1、设置TIMED_STATISTICS为True，可以在会话级别，也可以在实例级别。
会话级：
SQL> alter session set timed_statistics=True;
实例级：
SQL> alter system set timed_statistics=True scope=both;

2、 设置SQL_TRACE，可以在会话级，也可以在数据库级。
会话级：
SQL> alter session set sql_trace=true；
或者：
SQL>EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);
实例级：
SQL> alter system set sql_trace=true scope=both;

3、找到生成的trace文件，对trace文件使用tkprof 工具进行分析.

四．举例说明：

--启用SQL_TRACE
SQL> alter session set sql_trace=true;
会话已更改。
SQL> select count(*) from bigtab;

  COUNT(*)

----------

   1922423

--启用timed_statistics
SQL> alter session set timed_statistics=true;

会话已更改。

SQL>  select count(*) from bigtab;

  COUNT(*)

----------

   1922423

SQL>  alter session set sql_trace =false;

会话已更改。

--查询此会话产生的TRACE文件
SQL> select username,sid,serial# from v$session where username='SYS';

USERNAME                              SID    SERIAL#

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

SYS                                    19       2518

SQL> select 'orcl_ora_'||spid||'.trc' from v$process where addr = (select paddr from v$session where sid=19);

'DSS_ORA_'||SPID||'.TRC'

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

orcl_ora_7240.trc

也可以通过下面的函数来获取当前的trace文件：

create or replace function gettracename  return varchar2 is
  v_result varchar2(200);
begin
  SELECT    d.VALUE
      || '/'
      || LOWER (RTRIM (i.INSTANCE, CHR (0)))
      || '_ora_'
      || p.spid
      || '.trc' into v_result
  FROM (SELECT p.spid
          FROM v$mystat m, v$session s, v$process p
        WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,
      (SELECT t.INSTANCE
          FROM v$thread t, v$parameter v
        WHERE v.NAME = 'thread'
          AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,
      (SELECT VALUE
          FROM v$parameter
        WHERE NAME = 'user_dump_dest') d; 
  return v_result;
end gettracename;

运行SQL> select gettracename() from dual;即可
SQL> select gettracename() from dual;

GETTRACENAME()

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

d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc

--使用tkprof分析trace文件
C:/Users/Administrator.DavidDai>tkprof d:/app/administrator/diag/rdbms/orcl/orcl

/trace/orcl_ora_7240.trc D:/orcl_ora_7240.txt 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.

--tkprocf输出了以下文件：D:/orcl_ora_7240.txt 

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.

Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc

Sort options: 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

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows

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

Parse        4      0.00       0.00          0          0          0           0

Execute      5      0.00       0.00          0          0          0           0

Fetch        4      0.79       7.45      57075      57082          0           2

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

total       13      0.79       7.45      57075      57082          0           2

Misses in library cache during parse: 3

Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows

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

Parse        0      0.00       0.00          0          0          0           0

Execute      0      0.00       0.00          0          0          0           0

Fetch        0      0.00       0.00          0          0          0           0

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

total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

    5  user  SQL statements in session.

    0  internal SQL statements in session.

    5  SQL statements in session.

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

Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc

Trace file compatibility: 11.1.0.7

Sort options: fchela  

       1  session in tracefile.

       5  user  SQL statements in trace file.

       0  internal SQL statements in trace file.

       5  SQL statements in trace file.

       5  unique SQL statements in trace file.

      73  lines in trace file.

      75  elapsed seconds in trace file.

五.  分析会话的示例：
先从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.

这里生成的allan.txt文件就是我们最终得到的格式化后的trace文件了，然后打开这个文件进行分析。
最后总的统计：
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call    count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------   --------
Parse     20      0.01       0.02          0         58         0           0
Execute 13197     0.81       0.90         17       7436     6316          1484
Fetch   12944    22.86      22.10         20    2205941        0          8972
------- ------  -------- ---------- ---------- ---------- ---------- --------
total    26161     23.68     23.02         37    2213435     6316       10456

TKPROF 工具

                Oracle 官网的资料：

                                Using Application Tracing Tools

                        http://download.oracle.com/docs/cd/E11882_01/server.112/e10821/sqltrace.htm#PFGRF010

SQL_TRACE 生成最原始的trace文件的可读性比较差，所以通常我们使用tkprof 工具来处理trace文件。 Tkprof 工具是Oracle 自带的一个工具，用于处理原始的trace文件，它的作用主要是合并汇总trace文件中的一些项，规范化文件的格式，使文件更具有可读性。

注意：tkprof 工具只能用在处理SQL_TRACE和10046事件产生的trace，其他事件如10053不能处理。

 

                以前也整理过一篇文章：

                                使用 Tkprof 分析 ORACLE 跟踪文件

             

               

                刚才看了一些，也是比较粗糙，不详细，重新在整理一下。 Tkprof 是系统级别的，直接在系统下执行即可。先看一下tkprof的帮助文档：

 

C:/Users/Administrator.DavidDai>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

 

这个帮助对tkprof工具的参数做了说明。

 

2.1  explain=user/password

                在trace文件中输入SQL的执行计划，需要注意的是，如果不使用explain，在trace 文件中我们看到的是SQL实际的执行路劲。 如果使用了explain，tkprof在trace文件中不但输入SQL的实际执行路径，还会生成该SQL的执行计划。

 

2.2 sys=no

                如果设置为yes，在trace 文件中将输入所有的SYS用户的操作，也包含用户SQL语句引发的递归SQL。

如果为no，则不输出这些信息。

 

不过默认情况下是yes，实际上设置为no后，trace文件具有更佳的可读性，因此一般在用tkprof工具时都手工的把该参数设置为no。

 

 

2.3 aggregate=yes|no

                默认情况下，tkprof工具将所有相同的SQL在输入文件中做合并，如果设置为no，则分别列出每个SQL的信息。一般合并后看起来比较简洁，如果需要查看每一个SQL单独的信息，可以把aggregate设置为no。

 

2.4 查看第一节中生成的trace文件

 

C:/Users/Administrator.DavidDai>cd d:/app/administrator/diag/rdbms/orcl/orcl/trace

C:/Users/Administrator.DavidDai>D:

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>tkprof orcl_ora_3048_安庆怀宁.trc 安徽安庆怀宁.txt sys=no

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

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

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>

 

生成的 安徽安庆怀宁.txt文件内容如下：

 

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

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

 

Trace file: orcl_ora_3048_安庆怀宁.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

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

# 以上文件头信息描述了tkprof的版本信息，以及报告中一些列的含义

 

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS   #非递归SQL语句

 

call     count       cpu    elapsed       disk      query    current        rows

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

Parse        4      0.01       0.03          0          0          0           0

Execute      5      0.00       0.00          0          0          0           2

Fetch       67      0.00       0.00          0        140          0         980

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

total       76      0.01       0.03          0        140          0         982

 

 

Misses in library cache during parse: 2  #shared pool 中没有命令，说明做了2次硬解析，软解析此处为0

Oracle SQL的硬解析和软解析

http://blog.csdn.net/tianlesoftware/archive/2010/04/08/5458896.aspx

 

Misses in library cache during execute: 1

 

 

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS   #递归SQL语句

 

call     count       cpu    elapsed       disk      query    current        rows

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

Parse        5      0.00       0.00          0          0          0           0

Execute     57      0.00       0.00          0          0          0           0

Fetch      113      0.00       0.00          0        176          0         110

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

total      175      0.00       0.00          0        176          0         110

 

Misses in library cache during parse: 0

 

    5  user  SQL statements in session.

   57  internal SQL statements in session.

   62  SQL statements in session.

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

Trace file: orcl_ora_3048_安庆怀宁.trc

Trace file compatibility: 11.1.0.7

Sort options: default

 

       3  sessions in tracefile.

      10  user  SQL statements in trace file.

     114  internal SQL statements in trace file.

      62  SQL statements in trace file.

       9  unique SQL statements in trace file.

     613  lines in trace file.

      27  elapsed seconds in trace file.

 

 

2.5 查看trace 文件

                在2.4中，我们看到了tkprof生成的报告，这个报告是一个汇总的结果集，如果想确切的知道SQL 语句的每一步执行是如果操作的，就需要分析原始的trace文件。这个trace 虽然没有tkprof工具处理之后易读，但是却能够清楚的知道SQL在那个点做了什么，以及SQL是如何工作的，这对与理解SQL语句的执行过程非常有用。

 

直接打开 orcl_ora_3048_安庆怀宁.trc 文件：

 

Trace file d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048_安庆怀宁.trc

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

Windows NT Version V6.1 

CPU                 : 2 - type 586, 2 Physical Cores

Process Affinity    : 0x0x00000000

Memory (Avail/Total): Ph:1559M/4095M, Ph+PgF:4170M/8188M, VA:2881M/4095M

Instance name: orcl

Redo thread mounted by this instance: 1

Oracle process number: 29

Windows thread id: 3048, image: ORACLE.EXE (SHAD)

 

 

*** 2010-09-01 23:45:51.877

*** SESSION ID:(267.996) 2010-09-01 23:45:51.877

*** CLIENT ID:() 2010-09-01 23:45:51.877

*** SERVICE NAME:(SYS$USERS) 2010-09-01 23:45:51.877

*** MODULE NAME:(sqlplus.exe) 2010-09-01 23:45:51.877

*** ACTION NAME:() 2010-09-01 23:45:51.877

 

……..

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

PARSING IN CURSOR #12 len=493 dep=1 uid=0 oct=3 lid=0 tim=488541717777 hv=2584065658 ad='b1dad758' sqlid='1gu8t96d0bdmu'

select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)

END OF STMT

PARSE #12:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541717773

EXEC #12:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541718176

FETCH #12:c=0,e=127,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2035254952,tim=488541718359

STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op='MERGE JOIN OUTER (cr=4 pr=0 pw=0 time=0 us cost=2 size=189 card=1)'

STAT #12 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=137 card=1)'

STAT #12 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'

STAT #12 id=4 cnt=0 pid=1 pos=2 obj=0 op='BUFFER SORT (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

STAT #12 id=5 cnt=0 pid=4 pos=1 obj=429 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

STAT #12 id=6 cnt=0 pid=5 pos=1 obj=430 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'

CLOSE #12:c=0,e=11607,dep=1,type=3,tim=488541730026

…………

 

这个文件的可读性要差很多。 对这里面的一些参数做些说明：

 

PARSING IN CURSOR 部分：   

                Len: 被解析SQL的长度

                Dep: 产生递归SQL的深度

                Uid：user id

                Otc: Oracle command type 命令的类型

                Lid: 私有用户id

                Tim：时间戳

                Hv： hash value

                Ad：SQL address

 

PARSE,EXEC,FETCH 部分

                C: 消耗的CPU time

                E：elapsed time 操作的用时

                P: physical reads 物理读的次数

                Cr: consistent reads 一致性方式读取的数据块

                Cu：current 方式读取的数据块

                Mis：cursor misss in cache 硬分析次数

                R: -rows 处理的行数

                Dep: depth 递归SQL的深度

                Og： optimizer goal 优化器模式

                Tim：timestamp时间戳

 

STATS 部分：

                Id: 执行计划的行源号

                Cnt：当前行源返回的行数

                Pid：当前行源号的父号

                Pos：执行计划中的位置

                Obj：当前操作的对象id（如果当前行原始一个对象的话）

                Op：当前行源的数据访问操作