Path: news.easynews.com!core-easynews!newsfeed3.easynews.com!easynews.com!easynews!news.glorb.com!postnews2.google.com!not-for-mail From: mathewbutler@yahoo.com (Matt) Newsgroups: comp.databases.oracle.server Subject: Re: Odd maximum elapsed event times in raw 10046 trace Date: 8 Aug 2004 18:14:33 -0700 Organization: http://groups.google.com Lines: 160 Message-ID: <19f48a45.0408081714.36f797d8@posting.google.com> References: <19f48a45.0408032226.1c874ffb@posting.google.com> <41114320$1@post.usenet.com> <19f48a45.0408051714.524bf34a@posting.google.com> NNTP-Posting-Host: 202.53.62.34 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 8bit X-Trace: posting.google.com 1092014073 15952 127.0.0.1 (9 Aug 2004 01:14:33 GMT) X-Complaints-To: groups-abuse@google.com NNTP-Posting-Date: Mon, 9 Aug 2004 01:14:33 +0000 (UTC) Xref: core-easynews comp.databases.oracle.server:227827 X-Received-Date: Sun, 08 Aug 2004 18:13:30 MST (news.easynews.com) 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@dial.pipex.com (Niall Litchfield) wrote in message news:... > mathewbutler@yahoo.com (Matt) wrote in message news:<19f48a45.0408051714.524bf34a@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" wrote in message news:<41114320$1@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 > > > -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=