Ram,
Events (and other information) are written to trace files upon
completion, so it makes sense that nothing is written for a long time
and we can determine that the last completed instrumented event was a
read request. Before you terminated the session, the last fetch had
performed a few physical reads and over 4 million logical reads. And
this took over 3,485 seconds (almost 1 hour) and almost all of this was
in CPU time. Either each logical i/o is taking a long time (a quick
check of some historical trace files on other systems I work with show
about 1 million lios with about 10 seconds of CPU time) or there is
something else using a lot of cpu time. I don't think tracing the
logical i/o will show you much, but you might want to check on events
that expose sort information. Again...do not use these events on a
production system! You might want to raise an SR w/Oracle to see if they
can assist.
--
Daniel Fink
Oracle Performance, Diagnosis and Training
OptimalDBA http://www.optimaldba.com
Oracle Blog http://optimaldba.blogspot.com
Join me at Miracle Scotland DB Forum!
http://www.miracleltd.com/index.asp?page=167&page2=343
Ram Raman wrote:
> I tried running the 10046 on the good results and the hanging query.
> The trace file generated for the hanging query gets written to in the
> first minute of kicking off the query. After that it does not get
> updated at all, even after 1.5 hrs. I killed the query.
>
> Here is the last few lines from the trace file:
>
> WAIT #3: nam='db file sequential read' ela= 325 p1=71 p2=42927 p3=1
> WAIT #3: nam='db file scattered read' ela= 744 p1=71 p2=42929 p3=4
> WAIT #3: nam='db file scattered read' ela= 733 p1=71 p2=42933 p3=6
> WAIT #3: nam='db file sequential read' ela= 22 p1=71 p2=42940 p3=1
> WAIT #3: nam='db file sequential read' ela= 323 p1=71 p2=42942 p3=1
> WAIT #3: nam='db file sequential read' ela= 317 p1=71 p2=42944 p3=1
> WAIT #3: nam='db file scattered read' ela= 79393 p1=71 p2=42946 p3=2
> WAIT #3: nam='db file sequential read' ela= 2118 p1=71 p2=42948 p3=1
> WAIT #3: nam='db file scattered read' ela= 41 p1=71 p2=42950 p3=2
> WAIT #3: nam='db file scattered read' ela= 6953 p1=71 p2=42953 p3=10
> WAIT #3: nam='db file scattered read' ela= 5416 p1=71 p2=42978 p3=15
> WAIT #3: nam='db file scattered read' ela= 2531 p1=71 p2=42993 p3=15
> WAIT #3: nam='db file scattered read' ela= 19086 p1=71 p2=43008 p3=15
> WAIT #3: nam='db file scattered read' ela= 17044 p1=71 p2=43023 p3=15
> WAIT #3: nam='db file scattered read' ela= 11060 p1=71 p2=43038 p3=15
> WAIT #3: nam='db file sequential read' ela= 32 p1=71 p2=43054 p3=1
> WAIT #3: nam='db file scattered read' ela= 825 p1=71 p2=43056 p3=12
> WAIT #3: nam='db file scattered read' ela= 66 p1=71 p2=43068 p3=2
> <<<--- It was hanging here for 1.5 hrs, I killed the query at this point
> *** 2007-03-01 18:28:08.774
> FETCH
> #3:c=3460150000,e=3485042478,p=2211,cr=4712259,cu=0,mis=0,r=0,dep=0,og=4,ti
> m=1706202437810
> WAIT #3: nam='SQL*Net break/reset to client' ela= 335 p1=1650815232
> p2=0 p3=0
> WAIT #3: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
>
--
http://www.freelists.org/webpage/oracle-l
Received on Thu Mar 01 2007 - 20:21:21 CST
