Database Reference
In-Depth Information
The difference between the response time of 5.627 s and the elapsed time covered by the
trace file (max(tim)- min(tim): 74.957s) is just as prominent as in the TKPROF report. Contrary
to TKPROF, the ESQLTRCPROF report points out that there are 45 seconds which are not
accounted for (
unknown
). The total wait time of 50.974 s proves that the application was inter-
acting with the DBMS most of the time, but the wait time should be rolled up into parse, execute,
and fetch calls.
According to ESQLTRCPROF, the highest contributor to response time was associated
with a cursor that does not have a SQL statement text associated with it.
Statements Sorted by Elapsed Time (including recursive resource utilization)
==============================================================================
Hash Value: -1 - Total Elapsed Time (excluding think time): 2.976s
Cursor 0 - unknown statement (default container for any trace file entries relating
to cursor 0)
DB Call Count Elapsed CPU Disk Query Current Rows
------- -------- ---------- ---------- -------- -------- -------- --------
PARSE 0 0.0000s 0.0000s 0 0 0 0
EXEC 0 0.0000s 0.0000s 0 0 0 0
FETCH 0 0.0000s 0.0000s 0 0 0 0
------- -------- ---------- ---------- -------- -------- -------- --------
Total 0 0.0000s 0.0000s 0 0 0 0
Wait Event/CPU Usage/Think Time Duration Count
---------------------------------------- ---------- --------
SQL*Net message from client 2.431s 8081
think time 2.312s 71
log file sync 0.516s 86
SQL*Net message to client 0.028s 8152
latch: shared pool 0.001s 6
latch: library cache 0.000s 1
total CPU 0.000s 0
TKPROF does not have a sort option that incorporates wait time between database calls.
Hence it did not report this unknown statement as the highest contributor to response time.
What's wrong? Cursors without associated SQL statements? Wait time from intra database
call waits such as
direct path read
and
direct path write
, which is not rolled up into database
calls? Do both tools report incorrect results? A look at the extended trace file reveals that there
were 92956 wait events pertaining to cursor 4. However, the trace file did not contain a single
PARSING
IN
CURSOR
,
PARSE
,
EXEC
, or
FETCH
entry for cursor 4. The level 2
ERRORSTACK
dump taken
by the script
awr_capture.sql
contained the rather strange sqltxt value “table_e_a_d21e_
a_0_0” for cursor 4. Clearly, this was not an issue of a missing
PARSING
IN
CURSOR
entry due to the
fact that tracing was switched on in the midst of a running application. There simply did not
exist a proper SQL statement for this cursor.
