利用tkprof查看trace文件(原创)

生成trace文件

通过查看Oracle中的trace文件，往往有助于我们去分析数据库dump原因，执行计划的内部过程，绑定变量的使用情况，以及产生死锁的原因等等。我们可以通过如下3种方式手工生产trace文件
开启trace跟踪
会话级

SQL> alter session set sql_trace=true;
SQL> alter session set events '10046 trace name context forever,level 12';
SQL> exec sys.dbms_system.set_sql_trace_in_session(10 , 39196 , true);
实例级
SQL> alter system set sql_trace=true;
关闭trace跟踪
会话级
SQL> alter session set sql_trace=false;
SQL> alter session set events '10046 trace name context off';
SQL> exec sys.dbms_system.set_sql_trace_in_session(10 , 39196 , false);
实例级
SQL> alter system set sql_trace=false;
tkprof
语法
$ 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

这样可以减少分析出来的文件的复杂度，便于查看。

参数说明
tracefile：你要分析的trace文件
outputfile：格式化后的文件
explain=user/password@connectstring
table=schema.tablename

PRINT:只列出输出文件的最初N个SQL语句。默认为所有的SQL语句。
AGGREGATE:如果= NO，则不对多个相同的SQL进行汇总。如果为yes则对trace文件中的相同sql进行合并。
INSERT:SQL 语句的一种，用于将跟踪文件的统计信息存储到数据库中。在TKPROF创建脚本后，在将结果输入到数据库中。
SYS:如果设置为yes，则所有sys用户的操作(也包含用户sql语句引发的递归sql)，这样可以减少分析出来的文件的复杂度，便于查看。
TABLE:在输出到输出文件前，用于存放临时表的用户名和表名。
EXPLAIN:对每条SQL 语句确定其执行规划，并将执行规划写到输出文件中。如果不是有explain，在trace文件中我们看到的是SQL实际的执行路径，不会有sql的执行计划
sort:对trace文件的sql语句根据需要排序，其中比较有用的一个排序选项是fchela，即按照elapsed time fetching来对分析的结果排序（记住要设置初始化参数timed_statistics=true），生成的文件将把最消耗时间的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这步。
trace文件中的性能分析
1、如果分析数与执行数之比为1，说明每次执行这个查询都要进行sql解析。如果分析数与执行数之比接近0，则意味着查询执行了很多次软解析，降低了系统的可伸缩性。
2、如果trace文件中显示对所有或者几乎所有的sql都执行一次，那有可能是因为没有正确使用绑定变量。
3、如果一个(Fetch Count)/所获得行数的比值接近1，且行数大于1，则应用程序不执行大批量取数操作，每种语言/API都有能力完成这个功能，即一次取多行。如果没有利用这个功能进行批量去，将有可能花费多得多的时间在客户端与服务器端之间来回往返。这个过多的来回转换出了产生很拥挤的网络状况之外，也会比一次调用获得很多行要慢得多，如何指示应用程序进行批量获取将随语言/API而定。
4、如果CPU时间与elasped时间有巨大差异，意味着有可能花了大量时间在等待某些事情上。如果花了一个CPU时间来执行，但它却总共花了10秒的时间，这就意味着90%的运行时间在等待一个资源。例如被一个会话等待，或者大量查询时的物理IO等待等
5、较长的CPU或经过时间往往是最消耗资源的sql，需要我们关注
6、可以通过磁盘IO所占逻辑IO的比例，disk/query+current来判断磁盘IO的情况，太大的话有可能是db_buffer_size过小，当然这也跟SQL的具体特性有关
7、query+current/rows 平均每行所需的block数，太大的话（超过20）SQL语句效率太低，数据过于分散，可以考虑重组对象
trace文件样例

TKPROF: Release 10.2.0.1.0 - Production on Sun Apr 22 11:00:58 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
Trace file: orcl_ora_4299.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
********************************************************************************
The following statements encountered a error during parse:
BEGIN :a = 99; END;
Error encountered: ORA-06550
--------------------------------------------------------------------------------
alter session set sql_trace=off
Error encountered: ORA-00922
********************************************************************************
error connecting to database using: system/manager
ORA-01017: invalid username/password; logon denied
EXPLAIN PLAN option disabled.
********************************************************************************
select count(*)
from
 t where id = :a
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.03       0.04         99        106          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.05         99        106          0           1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=106 pr=99 pw=0 time=46182 us)
  50422   INDEX FAST FULL SCAN T_IDX (cr=106 pr=99 pw=0 time=4489223 us)(object id 52998)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.00       0.01          0          0          0           0
Execute     12      0.01       0.03          0          0          0           3
Fetch       10      0.07       0.08         99        316          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       32      0.09       0.13         99        316          0           8
Misses in library cache during parse: 8
Misses in library cache during execute: 8
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       47      0.03       0.05          0          0          0           0
Execute    210      0.05       0.07          0          0          0           0
Fetch      328      0.06       0.04          0        852          0         976
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      585      0.15       0.16          0        852          0         976
Misses in library cache during parse: 22
Misses in library cache during execute: 22
   12  user  SQL statements in session.
  210  internal SQL statements in session.
  222  SQL statements in session.
    0  statements EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_4299.trc
Trace file compatibility: 10.01.00
Sort options: fchela
       1  session in tracefile.
      12  user  SQL statements in trace file.
     210  internal SQL statements in trace file.
     222  SQL statements in trace file.
      30  unique SQL statements in trace file.
    2131  lines in trace file.
     130  elapsed seconds in trace file.
先看下面解释
The compilation of a SQL statement consists of two phases: the parse phase and the execute phase. When the time comes to parse a SQL statement, Oracle first checks to see if the parsed representation of the statement already exists in the library cache. If not, Oracle will allocate a shared SQL area within the library cache and then parse the SQL statement.
At execution time, Oracle checks to see if a parsed representation of the SQL statement already exists in the library cache. If not, Oracle will reparse and execute the statement. -- the error will come out from this step. could be various reaconsequentlyns why it was flushed out of lc.

Misses in library cache during parse：发生在解析的硬解析数量，如果是软解析则Misses in library cache during parse将为0
Misses in library cache during execute：发生在执行调用阶段的硬解析数量。如果在执行调用时没有硬解析发生，Misses in library cache during execute这一行将不存在。

执行计划分为两部分，第一部分称为行源操作(Row Source Operation )，是游标关闭且开启跟踪情况下写到跟踪文件中的执行计划。这意味着如果应用程序不关闭游标而重用它们的话，不会有新的针对重用游标的执行计划写入到跟踪文件中。第二部分，叫做执行计划 (Execution Plan)，是由指定了explain参数的TKPROF生成的。既然这是随后生成的，所以和第一部分不一定完全匹配。万一看到两者不一致，前者是正确的。两个执行计划都通过Rows列提供执行计划中每个操作返回的行数（不是处理的--要注意）。 对于每个行源操作来说，可能还会提供如下的运行时统计：
cr是一致性模式下逻辑读出的数据块数。
pr是从磁盘物理读出的数据块数。
pw是物理写入磁盘的数据块数。
time是以微秒表示的总的消逝时间。要注意根据统计得到的值不总是精确的。实际上，为了减少开销，可能用了采样。
cost是操作的评估开销。这个值只有在Oracle 11g才提供。
size是操作返回的预估数据量(字节数)。这个值只有在Oracle 11g才提供。
card是操作返回的预估行数。这个值只有在Oracle 11g才提供。

输出文件的结尾给出了所有关于跟踪文件的信息。首先可以看到跟踪文件名称、版本号、用于这个分析所使用的参数sort的值。然后，给出了所有会话数量与SQL语句数量。
Optimizer mode: ALL_ROWS表示优化器采用的是all_rows的模式
Parsing user id: 55 表示用户id为55
Tips:我们可以通过grep total report1.txt来快速查看需要我们关注的地方，如上例，如果我们认为需要和0.05相关的sql，我们可以直接打开report1.txt搜索0.05这个关键字

Examples of TKPROF Statement
This section provides two brief examples of TKPROF usage. For an complete example of TKPROF output, see "Sample TKPROF Output".
TKPROF Example 1
If you are processing a large trace file using a combination of SORT parameters and the PRINT parameter, then you can produce a TKPROF output file containing only the highest resource-intensive statements. For example, the following statement prints the 10 statements in the trace file that have generated the most physical I/O:
TKPROF ora53269.trc ora53269.prf SORT = (PRSDSK, EXEDSK, FCHDSK) PRINT = 10
TKPROF Example 2
This example runs TKPROF, accepts a trace file named examp12_jane_fg_sqlplus_007.trc, and writes a formatted output file named outputa.prf:
TKPROF examp12_jane_fg_sqlplus_007.trc OUTPUTA.PRF
EXPLAIN=scott/tiger TABLE=scott.temp_plan_table_a INSERT=STOREA.SQL SYS=NO
SORT=(EXECPU,FCHCPU)
This example is likely to be longer than a single line on the screen, and you might need to use continuation characters, depending on the operating system.
Note the other parameters in this example:

• The EXPLAIN value causes TKPROF to connect as the user scott and use the EXPLAIN PLAN statement to generate the execution plan for each traced SQL statement. You can use this to get access paths and row source counts.

Note:If the cursor for a SQL statement is not closed, then TKPROF output does not automatically include the actual execution plan of the SQL statement. In this situation, you can use the EXPLAIN option with TKPROF to generate an execution plan.

• The TABLE value causes TKPROF to use the table temp_plan_table_a in the schema scott as a temporary plan table.
• The INSERT value causes TKPROF to generate a SQL script named STOREA.SQL that stores statistics for all traced SQL statements in the database.
• The SYS parameter with the value of NO causes TKPROF to omit recursive SQL statements from the output file. In this way, you can ignore internal Oracle Database statements such as temporary table operations.
• The SORT value causes TKPROF to sort the SQL statements in order of the sum of the CPU time spent executing and the CPU time spent fetching rows before writing them to the output file. For greatest efficiency, always use SORT parameters.

参考至:《Oracle专家高级编程》 Thomas kyte 著
　　　《让Oracle跑得更快》谭怀远著
          http://suny628.blog.163.com/blog/static/61921533201143033127951/
          http://blog.csdn.net/tianlesoftware/article/details/5632003
          http://blog.csdn.net/fw0124/article/details/6899162
          http://www.zhishizhan.net/thread-717835-1-1.html
          http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94992
本文原创，转载请注明出处、作者
如有错误，欢迎指正
邮箱:[e-mail]