How a sort works?

First, allow me to apologize for our Lotus Notes throwing my ID in all 
caps.  If someone knows how to turn that annoyance off, please tell me!

We have a fairly sizeable sort order-by (1.2 million rows). 
V$session_longops shows that it takes a massive amount of time in this 
step.  I have traced the session with 10046.  I am working on tracing this 
with 10032 and 10033 events turned on, as well as statistics_level=all so 
I can get timings in the stat lines.

I see a big long fetch, then a bunch (190) repetitions of more data to 
client of around 2,000 bytes (all but one are of short duration), with 
some direct path reads sprinkled in.  I see a more data to client of a 
very long duration (in the middle of the 190), more of short duration, and 
then another long fetch (these steps repeat).


It looks like the really long "more data to client" time is suspiciously 
close to the fetch e - c time.

The way I'm thinking is this:  Oracle sorts some of the data, building a 
partial resultset, spews a bunch or rows off to the client, and waits for 
some sort output buffer to clear before throwing more rows into it.  The c 
time in the fetch is primarily sort time, and v$session longops is 
attributing all the time to the sort, in a rather misleading fashion.  The 
bottleneck is really how much data the client can take.  Am I correct in 
this line of thinking?  I'm also not sure what the long-duration more data 
to client is telling me.

Solaris 5.10, Oracle 9.2.0.8

<snip>
WAIT #3: nam='SQL*Net more data to client' ela= 19 p1=1413697536 p2=2000 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 84 p1=1413697536 p2=2001 
p3=0
WAIT #3: nam='direct path read' ela= 104 p1=203 p2=16661 p3=1
WAIT #3: nam='SQL*Net more data to client' ela= 148379 p1=1413697536 
p2=2001 p3=
0
WAIT #3: nam='SQL*Net more data to client' ela= 22 p1=1413697536 p2=2003 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 33 p1=1413697536 p2=2005 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 38 p1=1413697536 p2=1997 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 35 p1=1413697536 p2=2004 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 36 p1=1413697536 p2=1996 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 31 p1=1413697536 p2=2003 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 32 p1=1413697536 p2=2002 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 28 p1=1413697536 p2=1998 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 28 p1=1413697536 p2=2001 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 36 p1=1413697536 p2=2001 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 29 p1=1413697536 p2=2005 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 30 p1=1413697536 p2=1997 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 29 p1=1413697536 p2=2002 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 45 p1=1413697536 p2=2000 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 30 p1=1413697536 p2=2001 
p3=0
WAIT #3: nam='SQL*Net more data to client' ela= 37 p1=1413697536 p2=2006 
p3=0
FETCH 
#3:c=80000,e=223197,p=48,cr=0,cu=0,mis=0,r=10000,dep=0,og=3,tim=3397704949
096
*** 2007-11-27 14:27:24.028
WAIT #3: nam='SQL*Net message from client' ela= 55007450 p1=1413697536 
p2=1 p3=0

Other related posts: