TKPROF showing incomplete data

  • From: "Hameed, Amir" <amir.hameed@xxxxxxxxxxxxxxx>
  • To: "oracle-l@xxxxxxxxxxxxx" <oracle-l@xxxxxxxxxxxxx>
  • Date: Tue, 11 Jan 2022 21:15:02 +0000

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

Other related posts: