Hi folks,
This is a 3-node 11.2.0.4 RAC database. We traced an Oracle E-Business suite
job which essentially runs 10046 trace at level 8 under the hood. The job ran
for around ~21 minutes. TKPROF file was generated using the following command:
tkprof sys=y waits=y sort=fchela,exeela,prsela
The topmost statement in the TKP output shows the following:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.01 0.01 0 12 0 0
Fetch 1 12.92 219.28 48827 141443 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 12.94 219.30 48827 141455 0 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 114 0.01 0.14
db file sequential read 79807 0.30 344.05
gc current block 3-way 55 0.00 0.03
gc current block 2-way 1929 0.00 0.83
gc current block congested 25 0.00 0.01
latch: gc element 4 0.00 0.00
gc cr block 2-way 100 0.00 0.04
gc cr block congested 2 0.00 0.00
gc current grant busy 1 0.00 0.00
latch: cache buffers lru chain 1 0.00 0.00
********************************************************************************
When I look at the timing from all recursive and non-recursive statements, I
see the following which doesn't add up to the elapsed time it took for the job
to complete:
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.05 0.30 10 93 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.05 0.30 10 93 0 2
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 52 0.03 0.04 0 0 0 0
Execute 8834 0.70 0.77 0 5700 29 57
Fetch 8896 14.40 256.56 54240 175700 60 9292
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17782 15.15 257.38 54240 181400 89 9349
I then manually parsed the raw trace file for db file sequential read waits for
the cursor belonging to the statement shown above and the count of those waits
came out as 240,083 which was different from 79,807. When added up the time of
db file sequential read waits using a simple shell script, the cumulative time
came out as 989,857,507 microseconds or ~ 16.5 minutes which makes sense.
Sorry for the long preamble. The question is that the additional db file
sequential read waits do exist in the raw trace file but TKP doesn't seem to be
reporting all of them and only partially reporting them. Any idea what might be
causing it?
Thanks,
Amir