Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: Odd maximum elapsed event times in raw 10046 trace

Re: Odd maximum elapsed event times in raw 10046 trace

From: Niall Litchfield <niall.litchfield_at_dial.pipex.com>
Date: 6 Aug 2004 06:06:08 -0700
Message-ID: <b6beca79.0408060506.399d92ed@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 Fri Aug 06 2004 - 08:06:08 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US