Database Reference
In-Depth Information
Using TKPROF
As suggested in Chapter 3, TKPROF is executed with the following options:
tkprof <trace file> <output file> sys=no sort=prsela,exeela,fchela
To start the analysis of the output file, it's always good to take a look at the last few lines. In this specific case, it's
important to notice that the processing lasted about 14 seconds, that the application executed 10,000 SQL statements,
and that all SQL statements were different from each other (
user SQL statements
are equal to
unique SQL statements
).
1 session in tracefile.
10000 user SQL statements
in trace file.
0 internal SQL statements in trace file.
10000 SQL statements in trace file.
10000 unique SQL statements
in trace file.
120060 lines in trace file.
14 elapsed seconds
in trace file.
Next, it's time to check how long the execution of the first SQL statement listed in the output lasted. Remember,
thanks to the
sort
option that you have specified, the SQL statements were sorted according to their response times.
Interestingly enough, the response time (column
elapsed
) of the first cursor is less than a 100th of a second (0.00).
In other words, all SQL statements were executed in less than a 100th of a second. Actually, on average, an execution
lasted 1.4 milliseconds (14/10,000). This means the response time is certainly not due to a few long-running SQL
statements but to the high number of SQL statements processed in a short time.
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 1 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00
0.00
0 2 0 0
In such a situation, to know whether parsing is a problem, you must examine the section providing the overall
totals. According to the execution statistics, the parse time was responsible for about 95% (5.7/6) of the processing
time. This clearly shows that the database engine did nothing else besides parsing.
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10000 5.54
5.70
0 0 0 0
Execute 10000 0.17 0.15 0 0 0 0
Fetch 10000 0.13 0.14 0 23051 0 3048
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 30000 5.86
6.00
0 23051 0 3048
The following line also shows that each of the 10,000 parses was a hard parse. Note that even if a high percentage
of hard parses is usually not wanted, it's not necessarily a problem. It's just a clue that something may be suboptimal.
Misses in library cache during parse:
10000
