| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> Re: Timestamps in trace files (and other trace file oddities)
This is a multi-part message in MIME format.
--------------B3AE78C40CE97F43274CAA70 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit 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
--------------B3AE78C40CE97F43274CAA70
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;
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
fn:Daniel Fink
Received on Thu Jul 24 2003 - 09:50:57 CDT
 |
 |