Re: TKPROF showing incomplete data

Amir,

If you'd be willing to share your trace file with me, I'd be happy to send you a Method R Workbench profile for it.

Cary Millsap
Method R Corporation

Check out my NEW book, *Faster: How to Optimize a System <https://method-r.com/2021/12/23/faster/>*

On Tue, Jan 11, 2022 at 3:15 PM Hameed, Amir <amir.hameed_at_sleepnumber.com> wrote:

> 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