RE: Timestamps in trace files (and other trace file oddities)

My interpretation would be as follows:

The wait entries are written whenever a wait ends, so at 15:40:59.149 the session has just been waiting .00 seconds for a scattered read of 18 blocks. At 15:46:06.340 it just had been waiting on a latch free event. For the almost seven minutes between, it had not been waiting on any of the established wait events. It had either been processing the blocks returned, or it could have been waiting in the OS scheduler queue waiting for a cpu to become available - or both intermittendly. After coming out of the latch free wait, it found that the blocks it had previously read had been flushed from the buffer (not surprising after 7 minutes) and needed to read them again.

At 07:04 AM 7/24/2003 -0800, you wrote:
>(Tried sending this yesterday. I'll try again)
>
>Dan,
>I was running a 10046 (level 12) trace on an awful piece of PeopleSoft SQL
>today and got some really odd results in my trace file (8.1.7).
>
>*** 2003-07-23 15:40:59.149
>WAIT #1: nam='db file scattered read' ela= 0 p1=65 p2=6041 p3=18
>*** 2003-07-23 15:46:06.340
>WAIT #1: nam='latch free' ela= 1 p1=813986232 p2=66 p3=0
>*** 2003-07-23 15:47:53.851
>WAIT #1: nam='db file scattered read' ela= 0 p1=65 p2=6042 p3=17
>
>Two things struck me (three if it takes me too long to write this and I get
>home late). First, the timestamps show an elapsed time of ~7 minutes, but
>the trace file has ela=1 (one onehundredth of a second). The 7 minutes is
>closer to reality. Huh???
>
>Secondly, the first scattered read reads 18 blocks starting at 6041. Why
>does the next scattered read start at block# 6042?
>
>Any ideas?

Wolfgang Breitling
Oracle7, 8, 8i, 9i OCP DBA
Centrex Consulting Corporation Received on Thu Jul 24 2003 - 10:46:20 CDT