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-----
Daniel Fink
Sent: Thursday, July 24, 2003 11:49 AM
To: Multiple recipients of list ORACLE-L
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?
>
> Any ideas?
>
> Henry
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Henry Poras
INET: [EMAIL PROTECTED]
Fat City Network Services -- 858-538-5051 http://www.fatcity.com
San Diego, California -- Mailing list and web hosting services
---------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: [EMAIL PROTECTED] (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
