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

From: Henry Poras <hporas_at_etal.uri.edu>
Date: Wed, 23 Jul 2003 17:03:26 -0400
Message-Id: <25998.339266@fatcity.com>

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

-----Original Message-----
From: ml-errors_at_fatcity.com [mailto:ml-errors_at_fatcity.com]On Behalf Of Daniel Fink
Sent: Wednesday, July 23, 2003 11:04 AM
To: Multiple recipients of list ORACLE-L Subject: Re: Timestamps in trace files

Gudmundur,

	Where is this documented (so I can RTFM)?
	The one piece of this I don't quite understand is that the timestamp is not

emitted twice in a row. If the long time is the triggering event, why do I see a gap of 90 minutes (in another trace file)?

Daniel

Gudmundur Bjarni Josepsson wrote:
>
> Daniel,
>
> Perhaps someone else can explain this better but the documentation I've
> got on this says that the Oracle kernel emits timestamps when a long
> time has elapsed since the last line was emitted to the trace file.
> Long time is defined as tens of seconds.
>
> Gudmundur
>
> > -----Original Message-----
> > From: ml-errors_at_fatcity.com [mailto:ml-errors_at_fatcity.com] On
> > Behalf Of Daniel Fink
> > Sent: 22. júlí 2003 21:19
> > To: Multiple recipients of list ORACLE-L
> > Subject: Timestamps in trace files
> >
> >
> > I was perusing a 10046 trace file and I noticed that
> > timestamps are written to the trace file. Sometimes they were
> > very regular (3 minutes apart give or take 30 seconds) while
> > other times they were hours apart. I have noticed that two
> > timestamps are never written without any intervening
> > activity. Anyone have any idea on the reasoning behind the
> > timestamps and the 'triggering event'?
> >
> > Daniel
> >
>
> --
> Please see the official ORACLE-L FAQ: http://www.orafaq.net
> --
> Author: Gudmundur Bjarni Josepsson
> INET: gbj_at_index.is
>
> 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: ListGuru_at_fatcity.com (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
Received on Wed Jul 23 2003 - 16:03:26 CDT