Re: Unaccounted for time in 10046 trace file

From: Cary Millsap <cary.millsap_at_method-r.com>
Date: Fri, 13 Sep 2013 21:47:11 -0500
Message-Id: <04FCE2F1-440C-4447-8D0D-9FBBA6CF074F_at_method-r.com>



Amir,

To convince me that there actually is unaccounted-for time in your case, I'd need to see the raw trace file. I would certainly have to see the trace data to make any educated guess about what's causing it, if it does exist.

Cary Millsap
Method R Corporation

On Sep 13, 2013, at 2:48 PM, "Hameed, Amir" <Amir.Hameed_at_xerox.com> wrote:

> Hi,
> I ran a simple SELECT statement where I drove a FTS on a large table and then trace it at level 8. Below is the SQL statement:
> select /*+ full(MMT) */ count(*) from apps.mtl_material_transactions MMT ;
> Here is the output from TKPROF:
>
> call count cpu elapsed disk query current rows
> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
> Parse 1 0.01 0.00 0 0 0 0
> Execute 1 0.00 0.00 0 0 0 0
> Fetch 2 174.21 841.44 7852466 7853454 0 1
> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
> total 4 174.22 841.44 7852466 7853454 0 1
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total Waited
> ---------------------------------------- Waited ---------- ------------
> library cache lock 1 0.00 0.00
> library cache pin 1 0.00 0.00
> SQL*Net message to client 2 0.00 0.00
> Disk file operations I/O 123 0.00 0.00
> gc current block 3-way 1 0.00 0.00
> enq: KO - fast object checkpoint 3 0.01 0.01
> reliable message 1 0.00 0.00
> direct path read 1919 4.48 356.76
> gc cr block 2-way 31 0.00 0.01
> db file sequential read 201 0.03 0.63
> gc cr disk read 1 0.00 0.00
> SQL*Net message from client 2 0.00 0.00
> ********************************************************************************
>
> I am not able to reconcile the elapsed time and the discrepancy is just too much:
> elapsed - cpu = 667.22
> Total Waited = 357.4
> Unaccounted for time = 667.22 - 357.4 = 309.82
>
> I know that Cary Milsap has talked about unaccounted for time in TKPROF output but this gap is just too much. Any idea where to look for the missing time?
>
> Thanks,
> Amir
>
> --
> http://www.freelists.org/webpage/oracle-l
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Sat Sep 14 2013 - 04:47:11 CEST

Original text of this message