Re: Unaccounted for time in 10046 trace file
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>> -----Original Message-----
>> 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
>> 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
>>=200.00
>> 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 =
>> =
**************************************************************************=
>>=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-lReceived on Sat Sep 14 2013 - 12:11:43 CEST