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

Dan,

        I see what you are saying but something doesn't feel right (see, say, feel. Should be some pun in here about not making sense). CPU time of 7 minutes after a single read??? This is an ugly INSERT on a 5 table join, but that's about it. Unfortunately I don't think there is a way to measure service time at this granularity. Isn't it recorded in sesstat at the end of the transactions? Guess I'll go and double check that.

        Also, I remember an old paper by Craig Shallahamer that shows you don't get a full multi_block_read_count if a block is already in buffer cache (e.g. mbrc=8; p3=8,p3=8,p3=3,...The 3 is because the fourth block is already in memory. The cached block is already reflected in the trace numbers.)

        There is something very strange hear but I don't know what. Might be an interesting case to track db/os relationships (running on AIX 4.3)

Henry

-----Original Message-----
From: ml-errors_at_fatcity.com [mailto:ml-errors_at_fatcity.com]On Behalf Of Daniel Fink
Sent: Thursday, July 24, 2003 11:49 AM
To: Multiple recipients of list ORACLE-L Subject: Re: Timestamps in trace files (and other trace file oddities)

Henry,

        I'll make an attempt, but I am still learning a great deal about wait events and trace files. Cary, Mogens, Anjo, Tim, Jonathan, Wolfgang, et.al. are better authorities, so any corrections are very welcome.

        The time between waits is the elapsed time. If we equate elapsed time to response time, we must look at the two components of RT, wait time and service time. If the time differential is 7 minutes, x minutes is service time and y minutes is wait time. It is possible that only .01 seconds was wait time, while the remaining 6:59:99 was service time (i.e. cpu)

        I can't explain the scattered read issue. However, it is interesting to note that the # of blocks to be read is offset by 1 in the second wait event. Perhaps, the read request was issued, but the 65.6041 block was already in memory, so the read request was reissued minus that block. I'm not sure how the latch free enters into the picture, but I have a feeling that this wait is integral in the sequence of events.

Dan

Henry Poras 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?
Received on Thu Jul 24 2003 - 11:39:51 CDT