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

From: Daniel Fink <daniel.fink_at_sun.com>
Date: Thu, 24 Jul 2003 13:17:19 -0600
Message-Id: <26007.339475@fatcity.com>

This is a multi-part message in MIME format.

--------------F673123CE59F729740141D77
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit

Henry,
	I completely agree, something did not feel right (hence my obvious reluctance). I did a very poor job of trying to explain that we cannot extrapolate system waits/activity by looking at database waits/activity. I should have learned my lesson (bad dba...go sit in the corner) from a long email discussion with another list member where I was trying to understand a session issue by examining a single processes trace file.

	Wolgang's answer really nails the issue. What I think it comes down to is that wait events are only valid for what Oracle is waiting for internally. It cannot see what is happening at the system level. Some of the system activity it can determine by the call it is making. For example, when a request is sent to disk, it knows that it is waiting for the data to be returned. However, it does not know what is consuming the wait time. It could be that the disk service time is high or that there are

so many requests for the disk that they are being queued up. All the process knows is that the data has not been returned. As Wolfgang illustrated, the same thing happens at the CPU. I doubt that all 7 minutes were CPU, most likely there was a lot of intervening activity. All Oracle know was that it was not waiting on something to happen internally.

        I hope I've done better the second time around.

Dan

Henry Poras wrote:
>
> 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
>

--------------F673123CE59F729740141D77
Content-Type: text/x-vcard; charset=us-ascii;  name="daniel.fink.vcf"

Content-Transfer-Encoding: 7bit
Content-Description: Card for Daniel Fink
Content-Disposition: attachment;

 filename="daniel.fink.vcf"

begin:vcard
n:Fink;Daniel
tel;cell:303.808.3282
tel;work:303.272.3225
x-mozilla-html:TRUE
adr:;;;;;;
version:2.1
email;internet:daniel.fink_at_sun.com
title:DB Services Lead
x-mozilla-cpt:;-4832 Received on Thu Jul 24 2003 - 14:17:19 CDT