Hello all.
I have a situation in a raw sql trace file that is confusing me and wondering if any one has insight into what is happening.
The two lines in question are as follows:
WAIT #140537036532960: nam='db file scattered read' ela= 40 file#=5 block#=974863 blocks=9 obj#=98504 tim=59790685901656
WAIT #140537036532960: nam='db file scattered read' ela= 28 file#=5 block#=974880 blocks=5 obj#=98504 tim=59790727052317
Both lines report a very small elapsed time (40 and 28 us).
However subtracting the two timestamps (59790727052317 - 59790685901656) = 41,150,661 us = 41.1sec. Much more than the reported handful of microseconds in ela.
Oracle document "Interpreting Raw SQL_TRACE output (Doc ID 39817.1)" repeatedly states :
tim Timestamp.
Pre-Oracle9i, the times recorded by Oracle only have a resolution
of 1/100th of a second (10mS). As of Oracle9i some times are
available to microsecond accuracy (1/1,000,000th of a second).
The timestamp can be used to determine times between points in the trace file.
The value is the value in V$TIMER when the line was written.
The timer has platform-specific implementation differences.
If there are TIMESTAMPS in the file you can use the difference
between 'tim' values to determine an absolute time.
Questions:
Can anyone explain the discrepancy?
Is subtracting the two tim values still a valid method?
If so, what happened in that 41 seconds that even the raw trace file is not recording anything?
Is there another trace event that can be used to find out what is happening?
Supplemental information:
This is an Oracle 12.1.0.2 database.
The trace is on an web application submitting the statement. I am investigating a performance issue.
tkprof is not showing this SQL performing that poorly. However the application response is not acceptable.
Trace file parsing of the cursor:
=====================
PARSING IN CURSOR #140537036532960 len=8103 dep=0 uid=105 oct=3 lid=105 tim=59790656645498 hv=653041699 ad='2af2b29f0' sqlid='1hcyrc8mft813'
select upper(substr(ss.subject_first_name,1,1) || substr(ss.subject_middle_name,1,1) || substr(ss.subject_last_name,1,1)) initials,
END OF STM
Tkprof results for the statement:
| call | count | cpu | elapsed | disk | query | current | rows |
------- ------ -------- ---------- ---------- ---------- ---------- ----------
| Parse | 1 | 0.00 | 0.00 | 0 | 0 | 0 | 0 |
| Execute | 1 | 3.32 | 3.32 | 0 | 49 | 3 | 0 |
| Fetch | 0 | 0.00 | 0.00 | 0 | 0 | 0 | 0 |
------- ------ -------- ---------- ---------- ---------- ---------- ----------
| total | 2 | 3.32 | 3.32 | 0 | 49 | 3 | 0 |
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 105
Elapsed times include waiting on following events:
| Event waited on | Times Max. Wait Total Waited |
---------------------------------------- Waited ---------- ------------
| SQL*Net message to client | 1 | 0.00 | 0.00 |
| db file sequential read | 62 | 0.01 | 0.01 |
| db file scattered read | 133 | 0.06 | 0.18 |
| direct path write temp | 140 | 0.00 | 0.05 |
| direct path sync | 14 | 0.04 | 0.16 |
| reliable message | 30 | 0.00 | 0.00 |
| enq: RO - fast object reuse | 30 | 0.00 | 0.02 |
| direct path read temp | 1020 | 0.00 | 0.22 |
| latch: cache buffers chains | 1 | 0.00 | 0.00 |
********************************************************************************
(Sorry about the formatting above. Could not paste without the tables for some reason.)
Thanks
Andrew