TKProf Interpretation (9i and above) (Doc ID 760786.1)

TKProf Interpretation (9i and above) (Doc ID 760786.1)

PURPOSE

This document gives general advice on the use of TKProf.   本文档提供有关TKProf使用的一般建议
It supersedes the archived document :   它取代了已存档的文档

Document 32951.1 TKProf Interpretation (8i and below)

Additionally there is a video entitled "SQL Tuning Using TKProf" in the Oracle Database Learning Stream.   另外，在Oracle Database Learning Stream中有一个名为"SQL Tuning Using TKProf"的视频

SCOPE

For users needing advice on how to use TKProf.   对于需要有关如何使用TKProf的建议的用户。

DETAILS

TKProf is an executable that 'parses' Oracle trace files to produce more readable output.   TKProf是一个可执行文件，可格式化Oracle跟踪文件以产生更具可读性的输出。
In the default mode, all the information in TKProf is available from the base trace file.  在默认模式下，基本跟踪文件中提供了TKProf中的所有信息。
To produce a trace file from a session for interpretation see:   要从会话中生成跟踪文件以进行解释，请参见：

Document 376442.1 Recommended Method for Obtaining 10046 trace for Tuning  或参考文章：https://blog.csdn.net/u010692693/article/details/103081054
Document 21154.1 EVENT: 10046 "enable SQL statement tracing (including binds/waits)"

For TKProf Usage see:  有关TKProf的用法，请参见：

Document 29012.1 QREF: TKPROF Usage - Quick Reference

TKProf is also documented in the following manual:  以下手册还记录了TKProf

Oracle® Database Performance Tuning Guide
11g Release 1 (11.1)
Part Number B28274-02
Chapter 21 Using Application Tracing Tools

TKProf Structure

TKProf output for an individual cursor has the following structure:   单个游标的TKProf输出具有以下结构：

SELECT NULL FROM DUAL

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.00       0.00          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          3          0           1

Misses in library cache during parse: 0
Optimizer goal: FIRST_ROWS
Parsing user id: 271

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL DUAL (cr=3 pr=0 pw=0 time=21 us cost=1 size=1 card=1)


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
  SQL*Net message from client                     2        0.00          0.00

Overall the structure is:   总体结构为

• SQL Statement  SQL语句
• Parse/Execute/Fetch statistics and timings   
• Library Cache information  库缓存信息
• Row source plan
• Events waited for by the statement  语句等待的事件

Parse/Execute/Fetch statistics and timings

This section contains the bulk of the useful timing information for each statement. This can be used in conjunction with the 'Row source plan' and 'Events waited for by the statement' to give the full picture.
本节包含每个语句的大量有用时序信息。可以将其与'Row source plan' and 'Events waited for by the statement'结合使用显示完整情况。
Columns in the Parse/Execute/Fetch table have the following meanings:

call	Statistics for each cursor's activity are divided in to 3 areas: Parse/Execute/Fetch. A total is also calculated.
Parse	statistics from parsing the cursor. This includes information for plan generation etc.
Execute	statistics for the execution phase of a cursor
Fetch	statistics for actually fetching the rows
count	number of times each individual activity has been performed on this particular cursor
cpu	cpu time used by this cursor
elapsed	elapsed time for this cursor (includes the cpu time)
disk	This indicates the number of blocks read from disk. Generally it would be preferable for blocks to be read from the buffer cache rather than disk.
query	This column is incremented if a buffer is read in Consistent mode. A Consistent mode buffer is one that has been generated to give a consistent read snapshot for a long running transaction.
current	This column is incremented if a buffer is found in the buffer cache that is new enough for the current transaction and is in current mode (and it is not a CR buffer). This applies to buffers that have been read in to the cache as well as buffers that already exist in the cache in current mode.
rows	Rows retrieved by this step

Library Cache information

Tracing a statement records some information regarding library cache usage which is externalised by TKProf in this section. Most important here is "Misses in library cache during parse:" which shows whether or not a statement is being re-parsed. If a statement is being shared well then you should see a minimal number of misses here (1 or 0 preferably). If sharing is not occurring then high values in this field can indicate that.  跟踪一条语句记录了有关库高速缓存使用情况的一些信息，这部分信息由TKProf在本节中进行了外部化。此处最重要的是"Misses in library cache during parse:"，它显示是否正在重新解析一条语句。如果一条语句被很好地共享，那么您应该在此处看到最少的未命中次数（最好是1或0）。如果没有发生共享，则此字段中的high values可以表明这一点。

Row source plan
This section displays the access path used at execution time for each statement along with timing and actual row counts returned by each step in the plan. This can be very useful for a number of reasons.   本节显示执行时每个语句使用的访问路径，以及计划中每个步骤返回的时间和实际行数。由于多种原因，这可能非常有用。

Row source plans are generated from STAT lines in the raw trace.  Row source plans是从原始Trace中的STAT行生成的。
STAT lines are written to trace every now and then, but sometimes, if the cursor is not closed cleanly then STAT lines will not be recorded and then the row source plan will not be displayed. Setting SQL_TRACE to false DOES NOT close all cursors. Cursors are closed in SQL*Plus immediately after execution. The safest way to close all cursors is to cleanly exit the session in question. See:   有时会不时地写入STAT行以进行跟踪，但有时，如果没有完全关闭游标，则不会记录STAT行，因此将不会显示行源计划。将SQL_TRACE设置为false不会关闭所有游标。执行后，将立即在SQL * Plus中关闭游标。关闭所有游标的最安全方法是干净地退出相关会话。看到：

Document 312368.1 Why Row Source Plans or Row Counts are Missing in TKPROF Output

For details of interpreting 10046 output see:   有关解释10046输出的详细信息，请参见，或参考文章:https://blog.csdn.net/u010692693/article/details/103084883

Document 39817.1 Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output

Example:

Rows     Row Source Operation
-------  ---------------------------------------------------
 [A]  1  TABLE ACCESS FULL DUAL [B] (cr=3 [C] pr=0 [D] pw=0 [E] time=21 us [F] cost=7 [G] size=7 [H] card=1 [I])

• Row count [A]- the row counts output in this section are the actual number of rows returned at each step in the query execution. These actual counts can be compared with the estimated cardinalities (row counts) from an optimizer explain plan. Any differences may indicate a statistical problem that may result in a poor plan choice.   行数[A] -本节中输出的行数是查询执行中每个步骤返回的实际行数。可以将这些实际计数与优化程序说明计划的估计基数（行计数）进行比较。任何差异都可能表明存在统计问题，可能导致计划选择不当。
  See:

  Document 214106.1 Using TKProf to compare actual and predicted row counts

• Row Source Operation [B] - Shows the operation executed at this step in the plan.   行源操作[B] -显示计划中此步骤执行的操作。
• IO Stats - For each step in the plan, [C] is the consistent reads, [D] is the physical reads and [E] is the writes. These statistics can be useful in identifying steps that read or write a particularly large proportion of the overall data.  IO统计-对于计划中的每个步骤，[C]是一致的读取，[D]是物理读取，[E]是写入。这些统计信息可用于识别读取或写入总数据中很大一部分的步骤。
• Timing - [F] shows the cumulative elapsed time for the step and the steps that preceded it in microseconds (µs: 1/1000000 of a second). This section is very useful when looking for the point in an access path that takes all the time. By looking for the point at where the majority of the time originates it is possible to narrow down a number of problems.  计时- [F]显示该步骤及其之前的步骤的累计经过时间，以微秒为单位（µs：1/1000000秒）。在需要花费所有时间的访问路径中寻找该点时，此部分非常有用。通过寻找大部分时间的起源点，可以缩小许多问题的范围。
• On later releases, row source trace has been enhanced to include some optimizer information. [G] is the estimated cost of the operation used by the optimizer for internal comparison, [H] is the estimated space usage of the operation in bytes and [I] is estimated cardinality (number of rows returned) of that particular operation.  在更高版本中，行源跟踪已得到增强，以包含一些优化程序信息。[G]是优化器用于内部比较的估计操作成本，[H]是估计的操作空间使用字节数，[I]是该特定操作的估计基数（返回的行数）。

Note that TKProf also contains an explain plan feature which allows users to generate the explain plan the statement in question would use if it were to be executed NOW as the specified user. When looking at previously executed statements it is advisable not to use this option and to rely on the Row Source plans generated from the STAT lines in the trace, as above. See the TKProf section in:   请注意，TKProf还包含一个解释计划功能，该功能允许用户生成要在指定的用户名下立即执行该语句的解释计划。如上所述，在查看先前执行的语句时，建议不要使用此选项，而要依赖从跟踪中的STAT行生成的行源计划。请参阅以下内容中的TKProf部分：

 Document 199081.1 Overview Reference for SQL_TRACE, TKProf and Explain Plan

Events waited for by the statement
This section displays all wait events that a statement has waited for during the tracing.  This section can be very useful when used in conjunction with the statistics and row source information for tracking down the causes of problems associated with long wait times. High numbers of waits or waits with a long total duration may be candidates for investigation dependent on the wait itself.  本节显示跟踪期间语句等待的所有等待事件。与统计信息和行源信息结合使用时，此部分对于跟踪与长时间等待相关的问题的原因非常有用。大量等待或总持续时间长的等待可能取决于等待本身而成为调查的候选对象。

General Tips

If a system is performing sub-optimally then one potential way of diagnosing potential causes is to trace a typical user session and then use TKProf to format the output. The numerous sort options available can provide a useful way of organising the output by moving the 'top' statement in a particular category to the top of the list. A list of the sort options can be accessed by simply typing 'TKProf' at the command prompt.   如果系统性能欠佳，那么诊断潜在原因的一种可能方法是跟踪典型的用户会话，然后使用TKProf格式化输出。通过将特定类别中的'top'语句移到列表顶部，可用的众多排序选项可以提供一种有效的组织输出的方式。只需在命令提示符下键入'TKProf'即可访问排序选项列表。
A useful starting point is the 'fchela' sort option which orders the output by elapsed time spent fetching. The resultant .prf file will display the most time consuming SQL statement at the start of the file.  一个有用的起点是'fchela'排序选项，该选项根据所花费的经过时间对输出进行排序。生成的.prf文件将在文件开头显示最耗时的SQL语句。
For actions to deal with degraded query performance located in this manner see:   有关以这种方式处理查询性能下降的操作，请参见

Document 742112.1 Support Action Plan for Query Performance Degradation

Another useful parameter is sys=yes/no. This can be used to prevent SQL statements run as user SYS from being displayed. This can make the output file much shorter and easier to manage.   另一个有用的参数是sys=yes/no。这可以用来防止显示以用户SYS身份运行的SQL语句。这可以使输出文件更短并且更易于管理。
Remember to always set the TIMED_STATISTICS parameter to TRUE when tracing sessions as otherwise no time based comparisons can be made.  请记住，在跟踪会话时始终将TIMED_STATISTICS参数设置为TRUE，否则将无法进行基于时间的比较。

Potential TKProf Usage Examples

Spotting Relatively High Resource Usage   发现相对较高的资源使用率

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 |
-----------------------------------------------------------------------

This statement is a single execute of an update.   该语句是一次更新执行。

[H] shows that this query is visiting 297 buffers to find the rows to update  显示此查询正在访问297个buffers以查找要更新的行
[I] shows that only 3 buffer are visited performing the update  显示仅访问了3个缓冲区执行更新
[J] shows that only 1 row is updated.   显示仅更新了1行

Reading 297 buffers to update 1 rows is a lot of work and would tend to indicate that the access path being used is not particularly efficient. Perhaps there is an index missing that would improve the access performance?
读取297个buffers以更新1行是一项繁重的工作，并且倾向于指示所使用的访问路径不是特别有效。也许缺少索引可以改善访问性能？

Spotting Over Parsing   发现解析

select ...

-------------------------------------------------------------------------
| call    | count |     cpu | elapsed | disk |  query | current |  rows |
|---------|-------|---------|---------|------|--------|---------|-------|
| Parse   | [M] 2 | [N] 221 |     329 |    0 |     45 |       0 |     0 |
| Execute |     3 | [O]   9 | [P]  17 |    0 |      0 |       0 |     0 |
| Fetch   |     3 |       6 |       8 |    0 | [L]  4 |       0 | [K] 1 |
-------------------------------------------------------------------------

Misses in library cache during parse: 2 [Q]

Here we have a select that we suspect may be a candidate for over parsing.
在这里，我们有一个select，我们怀疑它可能是过度解析的候选对象。
[K] is shows that the query has returned 1 row.   显示查询已返回1行​​​​​​​
[L] shows that 4 buffers were read to get this row back.  显示已读取4个buffers以返回该行。

This is fine.

[M] show that the statement is parsed twice - this is not desirable especially as the parse cpu usage is a high [N] in comparison to the execute figures : [O] & [P] (ie the elapsed time for execute is 17 seconds but the statement spends over 300 seconds to determine the access path etc in the parse phase. [Q] shows that these parses are hard parses. If [Q] was 1 then the statement would have had 1 hard parse followed by a soft parse (which just looks up the already parsed detail in the library cache). See:

[M]显示该语句被解析两次-这是不希望的，特别是因为与执行数字相比，解析cpu的使用率很高[N]：[O]＆[P]（即执行时间为17 [Q]表明这些解析是硬解析。如果[Q]为1，则该语句将进行1次硬解析，然后进行软解析。 （它只是在库缓存中查找已解析的详细信息）

Document 32895.1 SQL Parsing Flow Diagram

for more details.

This is not a particularly bad example in terms of total counts since the query has only been executed a few times. However if this pattern is reproduced for each execution this could be a significant issue. Excessive parsing should be avoided as far as possible by ensuring that code is shared:  就总数而言，这不是一个特别糟糕的示例，因为查询仅执行了几次。但是，如果每次执行都重现此模式，则可能是一个严重的问题。通过确保共享代码，应尽可能避免过多的解析：

• using bind variables   使用绑定变量
• make shared pool large enough to hold query definitions in memory long enough to be reused.   使共享池大到足以将查询定义保存在内存中足够长的时间以供重用。

See:

Document 62143.1 Understanding and Tuning the Shared Pool

Spotting Queries that Execute too frequently 

The following query has a high elapsed time and is a candidate for investigation:

UPDATE ...
SET ...
WHERE COL = :bind1;
    
call     count       cpu    elapsed       disk      query    current      rows
------- ------  -------- ---------- ---------- ---------- ----------  --------
Parse        0      0.00       0.00          0          0          0         0
Execute 488719  66476.95   66557.80          1     488729    1970566    488719
Fetch        0      0.00       0.00          0          0          0         0
------- ------  -------- ---------- ---------- ---------- ----------  --------
total   488719  66476.95   66557.80          1     488729    1970566    488719

From the above, the update executes 488,719 times and takes in total ~ 65,000 seconds to do this. The majority of the time is spent on CPU.  A single row is updated per execution. For each row updated ~1 buffer is queried. ~2 million buffers are visited to perform the update.  根据以上内容，更新执行了488,719次，总共花费了约65,000秒。大多数时间都花在CPU上。每次执行更新一行。对于每一行，查询约1个缓冲区。访问了约200万个缓冲区以执行更新。

On average the elapsed time is ~ 0.1 second per execution. A sub-second execution time would normally be acceptable for most queries, but if the query is not scaleable and is executed numerous times, then the time can quickly add up to a large number.  平均而言，每次执行所花费的时间约为0.1秒。对于大多数查询来说，亚秒级的执行时间通常是可以接受的，但是如果该查询不可伸缩且执行了多次，则该时间会迅速累加很多。

It would appear that in this case the update may be part of a loop where individual values are passsed and 1 row is updated per value. This structure does not scale with large number of values meaning that it can become inefficient.  看起来在这种情况下，更新可能是循环的一部分，其中传递了各个值，并且每个值更新了一行。此结构无法按比例缩放大量值，这意味着它可能变得效率低下。
  
One potential solution is to try to 'batch up'  the updates so that multiple rows are updated within the same execution. As Oracle releases have progressed a number of optimizations and enhancements have been made to improve the handling of 'batch' operations and to make them more efficient. In this way, code modifications to replace frequently executed relatively inefficient statements by more scaleable operations can have a significant impact.  一种可能的解决方案是尝试“分批”更新，以便在同一执行中更新多行。随着Oracle版本的发展，已经进行了许多优化和增强，以改进对“批处理”操作的处理并提高其效率。以这种方式，用更可伸缩的操作来替换经常执行的相对低效率的语句的代码修改可能会产生重大影响。

Trace File Elapsed Time Total Differs From Total SQL Time   跟踪文件经过的时间与SQL总时间不同

Sometimes you may see tkprof report that shows the elapsed time does not match the overall total for all recursive sql statements + overall total time for all non-recursive statements:  有时，您可能会看到tkprof报告，该报告显示所用时间与所有递归sql语句的总时间+所有非递归语句的总时间不匹配

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1                                 <---------Total non-recursive SQL is 0 seconds

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      101      0.23       0.53          0          1         22           0
Execute 11115914    713.48     849.96        183     281305       1021         213
Fetch   11115842   1080.26    2981.83        643  160564747          0    11121030
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   22231857   1793.97    3832.33        826  160846053       1043    11121243        <------------Total for all recursive SQL is 3,832 seconds


Trace file: support_ora_1111111_sample_.trc
Trace file compatibility: 11.1.0.7
Sort options: fchela  exeela  prsela  
       1  session in tracefile.
      47  user  SQL statements in trace file.
      24  internal SQL statements in trace file.
      71  SQL statements in trace file.
      42  unique SQL statements in trace file.
 52492692  lines in trace file.
   10538  elapsed seconds in trace file.           <--------------elapsed time in trace is 10,538 seconds

There appears to be 6706 missing in the trace file.   跟踪文件中似乎缺少6706

This is expected behavior if you start tracing a session that has already started.  如果您开始跟踪已经开始的会话，这是预期的行为。

To ensure that elapsed seconds matches the session total, you need to begin the tracing at the start of the session.  为确保经过的秒数与会话总数匹配，您需要在会话开始时开始跟踪。

REFERENCES

NOTE:199081.1 - SQL_TRACE (10046), TKProf and Explain Plan - Overview Reference
NOTE:214106.1 - Using TKProf to Compare Actual and Predicted Row Counts
NOTE:21154.1 - EVENT: 10046 "enable SQL statement tracing (including binds/waits)"
NOTE:29012.1 - QREF: TKPROF Usage - Quick Reference
NOTE:312368.1 - Why Row Source Plans or Row Counts are Missing in TKPROF Output
NOTE:376442.1 - * How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues
NOTE:39817.1 - Interpreting Raw SQL_TRACE output