Return-Path: Delivered-To: 2-oracle-l@orafaq.com Received: (qmail 7586 invoked from network); 3 Dec 2007 00:22:29 -0600 Received: from freelists-180.iquest.net (HELO turing.freelists.org) (206.53.239.180) by 69.64.49.119 with SMTP; 3 Dec 2007 00:22:29 -0600 Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id CC11B7CBF38; Mon, 3 Dec 2007 01:22:28 -0500 (EST) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 16085-03; Mon, 3 Dec 2007 01:22:28 -0500 (EST) Received: from turing (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 45B857CC0DB; Mon, 3 Dec 2007 01:22:28 -0500 (EST) Received: with ECARTIS (v1.0.0; list oracle-l); Mon, 03 Dec 2007 00:35:31 -0500 (EST) Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id D6C367CC891 for ; Mon, 3 Dec 2007 00:35:30 -0500 (EST) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 08646-04 for ; Mon, 3 Dec 2007 00:35:30 -0500 (EST) Received: from ug-out-1314.google.com (ug-out-1314.google.com [66.249.92.169]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 30A567CC981 for ; Mon, 3 Dec 2007 00:35:29 -0500 (EST) Received: by ug-out-1314.google.com with SMTP id y2so2822126uge for ; Sun, 02 Dec 2007 21:35:29 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:message-id:date:from:to:subject:cc:in-reply-to:mime-version:content-type:references; bh=x3/ETNjL1ybd0NrmBGl67ZM5bFVfmqIjx7QLjF8IIPU=; b=OEwZo1ao+K+G0mjyT2sH0ssO4QmdgACBm2C0sIMAVwcJhekPikshq3Sr3w8FI0T5uT3agyF4RP93CRDFw3XCjVngICffwZw2A3gdL0lc7OMNOqNgT95Ff/gsw4rybl3rKMwmjcL5BooHsjoXYMCLOSPFJIoRnUyZhiAaWMhef9g= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=received:message-id:date:from:to:subject:cc:in-reply-to:mime-version:content-type:references; b=SSW9mvZiBFZWmC70KKKt5aSTrd36qqOmS0d5bFzD/N8YD6iyepiENs9bkvQNnXnwcWa48QF6hCYITKVTOc4p2nJxEpDpd47sSQtSmYOO3DOvxe5JQrPRyTKNwo5nH0v/1IESKzeTmZfdlAk7CesZTzgh9E+hFBd8MonElfCXT1I= Received: by 10.66.248.5 with SMTP id v5mr3461547ugh.1196660129005; Sun, 02 Dec 2007 21:35:29 -0800 (PST) Received: by 10.67.122.20 with HTTP; Sun, 2 Dec 2007 21:35:28 -0800 (PST) Message-ID: <4415a5ed0712022135xf240e6cs1c07d8fd3551d098@mail.gmail.com> Date: Mon, 3 Dec 2007 13:35:28 +0800 From: "Eagle Fan" To: DEEDSD@nationwide.com Subject: Re: How a sort works? Cc: oracle-l@freelists.org In-Reply-To: MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_7795_20700881.1196660129004" References: X-archive-position: 3672 X-ecartis-version: Ecartis v1.0.0 Sender: oracle-l-bounce@freelists.org Errors-to: oracle-l-bounce@freelists.org X-original-sender: eagle.f@gmail.com Precedence: normal Reply-to: eagle.f@gmail.com List-help: List-unsubscribe: List-software: Ecartis version 1.0.0 List-Id: oracle-l X-List-ID: oracle-l List-subscribe: List-owner: List-post: List-archive: X-list: oracle-l X-Virus-Scanned: Debian amavisd-new at localhost.localdomain ------=_Part_7795_20700881.1196660129004 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline You can search for a doc "If your memory Serves you right" , wrote by Richmond Shee. On Dec 1, 2007 6:45 AM, wrote: > > 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 > > > 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 > > -- Eagle Fan Oracle DBA ------=_Part_7795_20700881.1196660129004 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline You can search for a doc "If your memory Serves you right" , wrote by Richmond Shee.

On Dec 1, 2007 6:45 AM, <DEEDSD@nationwide.com> wrote:

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




--
Eagle Fan

Oracle DBA ------=_Part_7795_20700881.1196660129004-- -- http://www.freelists.org/webpage/oracle-l