Odd maximum elapsed event times in raw 10046 trace

From: Matt <mathewbutler_at_yahoo.com>
Date: 3 Aug 2004 23:26:29 -0700
Message-ID: <19f48a45.0408032226.1c874ffb@posting.google.com>

I have a slow running application that runs on one win2K server that connects via a LAN connection to another physical database machine
(also Win2K; 9.2.0.4). I set up a logon trigger to capture a level 8
10046 trace. The important part of the response resource profile looks like this:

SQL*Net message from client:

Duration #Calls Av. Duration Min. Duration Max Duration 74.50% 60,464 0.070774s 0.000168s 1,711.972045s

db file scattered read:

Duration #Calls Av. Duration Min. Duration Max Duration 18.40% 1,890 0.557986s 0.000305s 993.615450s

CPU service:

Duration #Calls Av. Duration Min. Duration Max Duration 12.20% 75,442 0.009256s 0.000000s 304.703125s

I've noted some peculiarities in the trace

There is a single large SQL*Net message from client elapsed time that may be skewing my analysis.
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?

Can anyone please explain 2) above? Does this indicate a potential disk problem?

Thanks in advance to anyone interested enough to respond.

Mat.

Some more detail follows...

db file scattered read:

This is the largest contributor:

delete
from LOAD_AGGR_OUTPUT
WHERE LOAD_AGGRID = 10
AND LOAD_AGGR_SEQID = 946 Rows Row Source Operation (Object Id)

--------------- ----------------------------------------------------------------
              0 DELETE 
              0  TABLE ACCESS FULL LOAD_AGGR_OUTPUT(60342)

Looking in the raw trace file, I see that the maximum duration event
(ela= 993615450) is amongst some realistic reads times.

WAIT #1: nam='db file scattered read' ela= 45783 p1=13 p2=115209 p3=128
WAIT #1: nam='db file scattered read' ela= 48645 p1=13 p2=115721 p3=128
WAIT #1: nam='db file scattered read' ela= 42817 p1=13 p2=115977 p3=128
WAIT #1: nam='db file scattered read' ela= 43309 p1=13 p2=116233 p3=128
WAIT #1: nam='db file scattered read' ela= 45936 p1=13 p2=116617 p3=128
WAIT #1: nam='db file scattered read' ela= 44067 p1=13 p2=116873 p3=128
WAIT #1: nam='db file scattered read' ela= 993615450 p1=13 p2=117129 p3=128
WAIT #1: nam='db file scattered read' ela= 46654 p1=13 p2=117513 p3=128
WAIT #1: nam='db file scattered read' ela= 47450 p1=13 p2=117769 p3=128
WAIT #1: nam='db file scattered read' ela= 54867 p1=13 p2=118025 p3=128
WAIT #1: nam='db file scattered read' ela= 69897 p1=13 p2=118409 p3=128
WAIT #1: nam='db file scattered read' ela= 36496 p1=13 p2=118921 p3=128
WAIT #1: nam='db file scattered read' ela= 30544 p1=13 p2=119305 p3=128
WAIT #1: nam='db file scattered read' ela= 30123 p1=13 p2=119561 p3=128

SQL*Net message from client:

The following statement is top of the list of those that contribute this event.

Select Key_Value
From EV_Configuration
where Key_Name='DEBUG ERCOT IDR'

Rows Row Source Operation (Object Id)

--------------- ----------------------------------------------------------------
              0 TABLE ACCESS BY INDEX ROWID EV_CONFIGURATION(60308)
              0  INDEX UNIQUE SCAN PKEV_CONFIGURATION(60309)

Looking in the raw trace file, I see that the maximum duration event
(ela= 1711972045) is right at the end of the trace (as if the
application was just waiting for something to happen):

PARSING IN CURSOR #2 len=71 dep=0 uid=167 oct=3 lid=167 tim=18446744073245690322 hv=1646308576 ad='6b34261c' Select Key_Value From EV_Configuration where Key_Name='DEBUG ERCOT IDR'
END OF STMT
PARSE #2:c=0,e=8816,p=1,cr=49,cu=0,mis=1,r=0,dep=0,og=4,tim=18446744073245690313 WAIT #2: nam='SQL*Net message to client' ela= 4 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net message from client' ela= 220 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net message from client' ela= 195 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=1
EXEC #2:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744073245691041 WAIT #2: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #2: nam='SQL*Net message from client' ela= 365 p1=1413697536 p2=1 p3=0
WAIT #2: nam='db file sequential read' ela= 3192 p1=13 p2=32138 p3=1 FETCH #2:c=0,e=3289,p=1,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744073245694787 WAIT #2: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
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
WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 298 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=1 Received on Wed Aug 04 2004 - 01:26:29 CDT