Re: Odd maximum elapsed event times in raw 10046 trace

From: Niall Litchfield <niall.litchfield_at_dial.pipex.com>
Date: 9 Aug 2004 02:11:05 -0700
Message-ID: <b6beca79.0408090111.5be4cf44@posting.google.com>

mathewbutler_at_yahoo.com (Matt) wrote in message news:<19f48a45.0408081714.36f797d8_at_posting.google.com>...
> Niall,
>
> What you describe, seems plausible.

I think what I describe is plausible, the backward attribution is just wrong and I'm annoyed at myself at having posted it.

> 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.

I assume you are talking about this snippet from the trace file with a circa 28 minute wait on sqlnet?

WAIT #2: nam='SQL*Net message from client' ela= 338 p1=1413697536 p2=1 p3=0

STAT #2 id=1 cnt=0 pid=0 pos=1 obj=60308 op='TABLE ACCESS BY INDEX
ROWID EV_CONFIGURATION (cr=1 r=1 w=0 time=3275 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=60309 op='INDEX UNIQUE SCAN

PKEV_CONFIGURATION (cr=1 r=1 w=0 time=3271 us)' WAIT #2: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
*** 2004-08-04 11:08:43.234
WAIT #2: nam='SQL*Net message from client' ela= 1711972045 p1=1413697536 p2=1 p3=0

Now it looks like you have a between call event (as described on p103) here. (the STAT lines get written (in my understanding) only when the previous dbcall is finished.

From the extract you posted your other sqlnet message from client events are in the sub 500 microsecond range. Then suddenly we wait for 28 minutes. I'd *love* to know what the app/user was doing at this point. In other words - yes you should forward attribute - I was wrong - but is it actually reasonable to associate a 28 minute wait for the next dbcall to be issued with that dbcall, or have you in fact merely determined that 28 minutes of your response time is not attributable in any meaningful sense to the db at all (that would be my guess).

It also seems to me that I was misled by the term 'associated with' as meaning 'caused by'.

I'd rewrite my 'explanation' as

in db

wait   --- on dbfile.... #1
dbcall --- select 1 million rows. #1
wait   --- on sqlnet (and any others) #2
dbcall --- 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. in db

wait --- <this is the cause of the 28 minutes> sqlnet message #3 dbcall --- now issue another statement #3

--

Niall Litchfield
Oracle DBA
Audit Commission UK.

Received on Mon Aug 09 2004 - 04:11:05 CDT