Re: Unaccounted for time in 10046 trace file
- From: Frits Hoogland <frits.hoogland@xxxxxxxxx>
- To: Amir.Hameed@xxxxxxxxx
- Date: Sat, 14 Sep 2013 12:11:43 +0200
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@xxxxxxxxx
Phone: +31 6 14180860
On Sep 14, 2013, at 3:09 AM, "Hameed, Amir" <Amir.Hameed@xxxxxxxxx> =
wrote:
> There is plenty of CPU available on the server.
>=20
> -----Original Message-----
> From: Carlos Sierra [mailto:carlos.sierra.usa@xxxxxxxxx]=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@xxxxxxxxx> =
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@xxxxxxxxxxxxx =
[mailto:oracle-l-bounce@xxxxxxxxxxxxx] 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
>> --
>> //www.freelists.org/webpage/oracle-l
>>=20
>>=20
>>=20
>>=20
>> --
>> //www.freelists.org/webpage/oracle-l
>>=20
>>=20
> --
> //www.freelists.org/webpage/oracle-l
>=20
>=20
--
//www.freelists.org/webpage/oracle-l
Other related posts:
