Re: tim= values in trace file

On 1/5/06, Paul Baumgartel wrote:
>
> Do the timestamp values in Oracle10g trace files wrap? Note in the
> following that the timestamp of all of the fetch calls is less than that of
> the exec call.
>
> This particular query did in fact run for around 20 minutes; I'm trying to
> determine whether the CPU or elapsed value on the first FETCH call is
> correct (they can't both be correct, as the CPU is around double the
> elapsed).
>
> TIA.
>
> PARSING IN CURSOR #26 len=1221 dep=1 uid=16121 oct=3 lid=16121
> tim=8192891567 hv=3617545717 ad='acf1cb30'
> SELECT ...
> END OF STMT
> PARSE #26:c=0,e=3257,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=8192891556
> EXEC
> #26:c=46875,e=47706,p=0,cr=144,cu=0,mis=1,r=0,dep=1,og=1,tim=8192940296
> *** 2006-01-04 17:16:54.070
> FETCH
> #26:c=2222703125,e=1152767754,p=0,cr=1924,cu=0,mis=0,r=1,dep=1,og=1,tim=1152767754
> FETCH #26:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1152768071
> FETCH #26:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1152768173
> FETCH #26:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1152768264
> FETCH #26:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1152768353
> FETCH #26:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1152768449
>

They can wrap. In this case however I think its a bug where the e= value is getting set with the timestamp rather than the elapsed time. I'm almost certain that I have seen this documented on metalink.

--
Niall Litchfield
Oracle DBA
http://www.niall.litchfield.dial.pipex.com