It's possible it's applying undo to construct a CR image of the blocks y=
ou need. If you trace it with event 10201, level 1, you can see if this=
is the case. There will be a line that reads "Applying CR undo" for ea=
ch row of undo applied, and the sum of the lines that say "Applying CR u=
ndo" plus blocks from the sequential read waits (uhh, more or less) coul=
d match your FETCH cr reads lines.
- John
- Original Message -----
From: rjamya <rjamya_at_gmail.com>
To: Oracle Discussion List <oracle-l_at_freelists.org>
Sent: Tue, 26 Apr 2005 13:31:30 -0400
Subject: 10046 Trace question
> Hi all,
> I am testing performance of a query that produced some interesting out=
puts=20
> in the raw trace file. I cannot explain this, can someone=3F
>=20
> Raj
>=20
>=20
> ---------- Forwarded message ----------
> From: Jamadagni, Rajendra
>=20
> PARSING IN CURSOR #1 len=3D1540 dep=3D0 uid=3D44 oct=3D3 lid=3D44 tim=
=3D1088413968080921=20
> hv=3D3734675936 ad=3D'27ee5260'=20
> SELECT distinct pscp=5Fpa=5Fid, pr=5Fbrnd=5Fid, brnd=5Fname, pa=5Fagnc=
=5Fid, pa=5Fadvr=5Fid,=20
> ....
> END OF STMT=20
> PARSE
> #1:c=3D50000,e=3D62605,p=3D0,cr=3D109,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=
=3D0,tim=3D1088413968080915
>=20
> EXEC #1:c=3D0,e=3D655,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D0,og=3D4=
,tim=3D1088413968171161=20
> WAIT #1: nam=3D'SQL*Net message to client' ela=3D 23 p1=3D1650815232 p=
2=3D1 p3=3D0=20
> WAIT #1: nam=3D'global cache cr request' ela=3D 528 p1=3D32 p2=3D93812=
=20
> p3=3D504403158399474816=20
> WAIT #1: nam=3D'db file sequential read' ela=3D 460 p1=3D32 p2=3D93812=
p3=3D1=20
> WAIT #1: nam=3D'global cache cr request' ela=3D 446 p1=3D32 p2=3D93832=
=20
> p3=3D504403158349232736=20
> WAIT #1: nam=3D'db file sequential read' ela=3D 396 p1=3D32 p2=3D93832=
p3=3D1=20
> WAIT #1: nam=3D'db file sequential read' ela=3D 385 p1=3D31 p2=3D55448=
p3=3D1=20
> *** 2005-04-26 13:20:17.483=20
> FETCH
> #1:c=3D114080000,e=3D111402747,p=3D3,cr=3D817052,cu=3D0,mis=3D0,r=3D1,=
dep=3D0,og=3D4,tim=3D1088414079574042
>=20
> WAIT #1: nam=3D'SQL*Net message from client' ela=3D 1012 p1=3D16508152=
32 p2=3D1 p3=3D0=20
>=20
> FETCH #1:c=3D0,e=3D28,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D0,og=3D4=
,tim=3D1088414079575522=20
> WAIT #1: nam=3D'SQL*Net message to client' ela=3D 2 p1=3D1650815232 p2=
=3D1 p3=3D0=20
> WAIT #1: nam=3D'SQL*Net message from client' ela=3D 1137 p1=3D16508152=
32 p2=3D1 p3=3D0=20
>=20
> XCTEND rlbk=3D0, rd=5Fonly=3D1=20
>=20
> See the FETCH line, before that there are 3 'db file sequential reads'=
but=20
> FETCH line reports 817052 cr reads. It seems we are missing whle lot o=
f=20
> trace lines, but trust me, this is what I have. They query appears to =
hang,=20
> and then comes back. The difference between tim for PARSE and FETCH ag=
rees=20
> with e=3D value on the FETCH line.=20
>=20
> Am I interpreting this wrong=3F or should i expect to see many more li=
nes in=20
> here for cr reads=3F The trace is enabled by alter session 10046^12. I=
have=20
> trimmed the sqltext and binds information for obvious information.
>=20
> Any ideas=3F This is 9204 btw.
> Raj
> ------------------------------
> select standard=5Fdisclaimer from company=5Frequirements where categor=
y =3D=20
> 'MANDATORY';
>=20
> --
> http://www.freelists.org/webpage/oracle-l
>=20
--
http://www.freelists.org/webpage/oracle-l
Received on Tue Apr 26 2005 - 13:43:55 CDT
