TKPROF showing incomplete data

From: Hameed, Amir <amir.hameed_at_sleepnumber.com>
Date: Tue, 11 Jan 2022 21:15:02 +0000
Message-ID: <CH0PR14MB50125A77CAE78DB18EC0C417E0519_at_CH0PR14MB5012.namprd14.prod.outlook.com>



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

--
http://www.freelists.org/webpage/oracle-l
Received on Tue Jan 11 2022 - 22:15:02 CET

Original text of this message