Re: Help interpreting 10046 trace file anomaly

  • From: "Daniel W. Fink" <optimaldba@xxxxxxxxx>
  • To: oracle-l@xxxxxxxxxxxxx
  • Date: Thu, 06 May 2004 17:48:09 -0600


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: