Re: Unaccounted for time in 10046 trace file

From: Carlos Sierra <carlos.sierra.usa_at_gmail.com>
Date: Fri, 13 Sep 2013 16:30:18 -0500
Message-Id: <B7B73181-2402-4926-99BB-F9877A62B175_at_gmail.com>

You may want to look at the OS for possible CPU starvation.

Sent from my iPhone

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

> A bit of more information:
> * This is a four-node RAC environment
> * RDBMS version is 11.2.0.3.x
> * We are configured with DNFS
> -----Original Message-----
> From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Hameed, Amir
> Sent: Friday, September 13, 2013 3:48 PM
> To: 'ORACLE-L'
> Subject: Unaccounted for time in 10046 trace file
>
> 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
>
>

--
http://www.freelists.org/webpage/oracle-l

Received on Fri Sep 13 2013 - 23:30:18 CEST