In this Document
|Potential TKProf Usage Examples|
This document gives general advice on the use of TKProf.
It supersedes the archived document :
For users needing advice on how to use TKProf.
TKProf is an executable that 'parses' Oracle trace files to produce more readable output.
In the default mode, all the information in TKProf is available from the base trace file.
To produce a trace file from a session for interpretation see:
For TKProf Usage see:
TKProf is also documented in the following manual:
TKProf output for an individual cursor has the following structure:
Overall the structure is:
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.
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.
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.
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:
For details of interpreting 10046 output see:
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:
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.
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.
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.
For actions to deal with degraded query performance located in this manner see:
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.
Remember to always set the TIMED_STATISTICS parameter to TRUE when tracing sessions as otherwise no time based comparisons can be made.
Spotting Relatively High Resource Usage
This statement is a single execute of an update.
[H] shows that this query is visiting 297 buffers to find the rows to update
[I] shows that only 3 buffer are visited performing the update
[J] shows that only 1 row is updated.
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?
Spotting Over Parsing
Here we have a select that we suspect may be a candidate for over parsing.
[K] is shows that the query has returned 1 row.
[L] shows that 4 buffers were read to get this row back.
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:
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:
Spotting Queries that Execute too frequently
The following query has a high elapsed time and is a candidate for investigation:
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.
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.
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.
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/17252115/viewspace-1133374/，如需转载，请注明出处，否则将追究法律责任。