Re: Unaccounted for time in 10046 trace file

From: Frits Hoogland <frits.hoogland_at_gmail.com>
Date: Sat, 14 Sep 2013 12:11:43 +0200
Message-Id: <58668070-2D3D-4E71-9676-252395EC7372_at_gmail.com>

Content-Transfer-Encoding: quoted-printable Content-Type: text/plain;

        charset=us-ascii
You might want to run the trace file through orasrp: = http://www.oracledba.ru/orasrp/
But it might very well give you the same unaccounted for time.

The point with trace files is that any time not covered by a wait is = supposed to be CPU time. This means that if the processing gets stuck = (waiting, not for cpu) for whatever reason at a point which is not = instrumented, you get unaccounted for time, because oracle measures the = actual time spend on processing on cpu, besides measuring waits. so in = my point of view oracle does you a favour by telling there is = unaccounted for time. of course this doesn't mean it's easy to = understand where that time is spend.

Another point is CPU time gets attributed to the last process in the = timeslice of the operating system (at least on linux). So if your oracle = process voluntarily ends processing in the timeslice it has gotten, and = another process gets to use the timeslice, that is the process which = gets the CPU time accounted for. This means CPU accounted can be = inaccurate.

Please reads Cary Millsap's (and Jeff Holt's) "optimising oracle = performance", which fully explains this.

If you are lucky enough to run on linux and a kernel version 2.6.32 or = higher, you could use 'perf' to get an idea of where time is spend by = sampling the time spend in the c functions of a process or system wide.

Frits Hoogland

http://fritshoogland.wordpress.com
frits.hoogland_at_gmail.com
Phone: +31 6 14180860

On Sep 14, 2013, at 3:09 AM, "Hameed, Amir" <Amir.Hameed_at_xerox.com> = wrote:

> There is plenty of CPU available on the server.
>=20
> -----Original Message-----
> From: Carlos Sierra [mailto:carlos.sierra.usa_at_gmail.com]=20
> Sent: Friday, September 13, 2013 5:30 PM
> To: Hameed, Amir
> Cc: ORACLE-L
> Subject: Re: Unaccounted for time in 10046 trace file
>=20
> You may want to look at the OS for possible CPU starvation.=20
>=20
> Sent from my iPhone
>=20
> On Sep 13, 2013, at 2:54 PM, "Hameed, Amir" <Amir.Hameed_at_xerox.com> =

wrote:

>=20


>> 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

>>=20

>> 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:

>>=20
>> 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

>>=20


>> 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
>> =

**************************************************************************=

---

>>=20
>> I am not able to reconcile the elapsed time and the discrepancy is =
just too much:
>> elapsed - cpu =3D 667.22
>> Total Waited =3D 357.4
>> Unaccounted for time =3D 667.22 - 357.4 =3D 309.82
>>=20
>> 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?

>>=20

>> Thanks,
>> Amir

>>=20

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

>>=20
>>=20
>>=20
>>=20

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

>>=20
>>=20
> --
> http://www.freelists.org/webpage/oracle-l
>=20
>=20

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

Received on Sat Sep 14 2013 - 12:11:43 CEST