Re: Odd maximum elapsed event times in raw 10046 trace

Niall,

What you describe, seems plausible. Except for the fact that the Cary Millsap/Jeff Holt (Optimizing Oracle Performance) book describes using "forward attribution" ie: "You should attribute each wait #n duration to the first database call for cursor #2 that follows the WAIT line in the trace file". It's not that I take everything that I read as gospel, it's just that statement this tallys with my experience. Clearly something is going on that I don't yet understand.

Thanks for the response.

Mat.

niall.litchfield_at_dial.pipex.com (Niall Litchfield) wrote in message news:<b6beca79.0408060506.399d92ed_at_posting.google.com>...
> mathewbutler_at_yahoo.com (Matt) wrote in message news:<19f48a45.0408051714.524bf34a_at_posting.google.com>...
> > Cheers for the follow up Chris.
> >
> > > Since a COMMIT follow the 'SQL*Net message from client' the batch was either
> > > idle or doing some processing without db access.
> >
> > Here is what I see in the trace (along with my understanding of what
> > is occuring):
> >
> > PARSING IN CURSOR #2 -- Parse cursor #2 details
> > END OF STMT
> > PARSE #2 -- The parse of #2
> > WAIT #2: -- Waits on Exec for #2
> > ...
> > WAIT #2: -- Waits on Exec for #2
> > XCTEND rlbk=0, rd_only=1 -- A commit after a select (read only)
> > EXEC #2: -- Exec of cursor #2
> > WAIT #2: -- Wait in fetch of #2
> > ...
> > WAIT #2: -- Wait in fetch of #2
> > FETCH #2: -- fetch of #2
> > WAIT #2: -- Wait on cursor #2, but for which stage of processing?
> > ...
> > WAIT #2: -- Wait on cursor #2, but for which stage of processing?
> > ...
> > WAIT #2: -- Wait on cursor #2, but for which stage of processing?
> > WAIT #1: -- Wait on cursor #1, hang on which #1 ??
> > WAIT #1: -- Wait on cursor #1, hang on which #1 ??
> > XCTEND rlbk=0, rd_only=1 -- A commit after a select (read only)
> >
> > trace file finishes
> >
> > I expect that the batch was doing some processing. I have watched the
> > two machines (DB and application) resource utilisation and typically I
> > see much DB usage followed by a switch to the application which must
> > munch the data. It seemed peculiar to me though that the application
> > did this data processing after a query which appears to be a check for
> > a value in a configuration table (ev_configuration contains single row
> > lookups) - the 'SQL*Net message from client' was associated with
> > cursor #2:
> >
> > "Select Key_Value From EV_Configuration where Key_Name='DEBUG ERCOT
> > IDR'"
> >
> > I guess that the application could have been working hard with the
> > data retrieved from earlier cursors, quickly fired on cursor #2, and
> > the wait then got associated with #2 since this was the most recent
> > cursor. This doesn't quite sound right to me though...it doesn't match
> > with my current understanding of how waits tie to the PARSE, EXEC,
> > FETCH records, which I've pulled out of Cary Millsap and Jeff Holts
> > excellent book.
>
> The wait is associated with the previous #2 in the trace file.
>
> consider the following actions in a hypothetical batch program
>
> in db
> ======
> select 1 million rows. #1
> select value from lookup that tells me to update,delete or whatever #2
> in app
> ======
> find that I have to process the 1m rows. take ages.
> now issue another statement
> in db
> ======
> wait finishes and is written to trace file.
>
> It looks to me as if your app is doing something along these lines.
> Basically your large sqlnet message from client is actually telling
> you that the app is busy doing *something*. Of course if the *app* is
> instrumented you'd be able to tell what *it* is doing that takes so
> long.
>
> I concur that the disk read wait figure is just daft. I'd probably
> only investigate if there were multiple bad figures.
>
>
> Niall
>
>
>
>
>
>
>
>
>
> >
> > >> Can anyone please explain 2) above? Does this indicate a potential
> > >> disk problem?
>
> > >If it happen only once, I'll not take care of it, i.e. I'll "comment"
> the
> > >line from the tracefile for the analysis. If it occurs again and
> again,
> > >there's a problem somewhere. Of course the disk it's the first place
> to look
> > >at...
> >
> > The problem appears once only. I am investigating...
> >
> > Many Thanks.
> >
> > Mat.
> >
> > "Christian Antognini" <christian.antognini_at_trivadis.com> wrote in message news:<41114320$1_at_post.usenet.com>...
> > > **** Post for FREE via your newsreader at post.usenet.com ****
> > >
> > > Hi Matt
> > >
> > > > I've noted some peculiarities in the trace
> > > >
> > > > 1) There is a single large SQL*Net message from client elapsed time
> > > > that may be skewing my analysis.
> > > > 2) There is a single large db file scattered read elapsed times that
> > > > seems odd (as it falls inbetween a number of "standard" sized elapsed
> > > > values)
> > > >
> > > > As the application is a batch processor (third party). I am confused
> > > > by the large value from 1) above. could this simply be the time it
> > > > took me to switch off tracing?
> > >
> > > Since a COMMIT follow the 'SQL*Net message from client' the batch was either
> > > idle or doing some processing without db access.
> > >
> > > > Can anyone please explain 2) above? Does this indicate a potential
> > > > disk problem?
> > >
> > > If it happen only once, I'll not take care of it, i.e. I'll "comment" the
> > > line from the tracefile for the analysis. If it occurs again and again,
> > > there's a problem somewhere. Of course the disk it's the first place to look
> > > at...
> > >
> > >
> > >
> > > Chris
> > >
> > >
> > >
> > > -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
> > > *** Usenet.com - The #1 Usenet Newsgroup Service on The Planet! ***
> > > http://www.usenet.com
> > > Unlimited Download - 19 Seperate Servers - 90,000 groups - Uncensored
> > > -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Received on Sun Aug 08 2004 - 20:14:33 CDT