Re: Help interpreting 10046 trace file anomaly


It is important to remember that not all code is instrumented for 
timing, so the session could have performed some of that code. Another 
clue is that there is a timestamp emitted after the FETCH. I have see 
this occur if an entry is not emitted into the time stamp for a certain 
period of time (seems to be around 3 seconds). In looking at a couple of 
trace files from past tests, I see that the TIM values don't seem to 
true up with the e= values. So far, it has not had any impact in terms 
of mis-diagnosing a performance issue.

Daniel Fink

Aponte, Tony wrote:

>I need help understanding the time difference between the to "tim=" 
>values.  I calculated the difference to be (1007496616 - 1007492040) 
>4576.  But the time clocked in "SQL*Net message from client" is reported 
>as 1 centisecond.  The "***" line shows  that there was a long pause but 
>why doesn't the wait event account for the elapsed time?  This is the 
>first time I observe a discrepancy while walking the trace file.  Any 
>thoughts would be greatly appreciated.
>FETCH #4:c=0,e=0,p=0,cr=20,cu=0,mis=0,r=1,dep=0,og=3,tim=1007492040
>*** 2004-05-06 00:13:10.168
>WAIT #4: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1 p3=0
>PARSING IN CURSOR #4 len=422 dep=0 uid=22564 oct=3 lid=22564 tim=1007496616 
>hv=557190862 ad='eb942db8'
>Tony Aponte
>Home Shopping Network
>Please see the official ORACLE-L FAQ:
>To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
>put 'unsubscribe' in the subject line.
>Archives are at
>FAQ is at
Please see the official ORACLE-L FAQ:
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
Archives are at
FAQ is at

Other related posts: