Re: what could cause a high elap value for the exec system call (for a select statement)?

From: Tim Gorman <tim_at_evdbt.com>
Date: Wed, 04 Nov 2009 13:42:25 -0700
Message-ID: <4AF1E731.5070105_at_evdbt.com>



Freek (sorry for error on names earlier),

My error -- filtering on HAVING clause can be done during retrieval just as can filtering through a WHERE clause (without GROUP BY, ORDER BY, or FOR UPDATE OF), so I apologize for going too far with that particular after-thought. It was I who needed coffee prior to responding.

Although my responses were all irrelevant when they were not in error, you received several good pointers from Cary, Ric, Mark, Dan, and Brandon -- please share your findings?

Thanks!

Tim Gorman
consultant - Evergreen Database Technologies, Inc. P.O. Box 630791, Highlands Ranch CO 80163-0791

website   = http://www.EvDBT.com/
email     = Tim_at_EvDBT.com
mobile    = +1-303-885-4526
fax       = +1-303-484-3608
Yahoo IM  = tim_evdbt



Ric Van Dyke wrote:
> Roger that Freek. The other thing to note is that this query is a soft parse (mis=0) and your original one was a hard parse (mis=1). Hard parses do seem to take more exec time then soft parses. But a large amount like you showed before I would think that there would have been a lot of BIND variables, but only 2 would seem very odd for that.
>
> I suspect that there is something going on in the recursive SQL as Cary noted.
>
>
>
> -----Original Message-----
> From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of D'Hooge Freek
> Sent: Wednesday, November 04, 2009 10:34 AM
> To: tim_at_evdbt.com; mwf_at_rsiz.com; 'Daniel Fink'; Brandon.Allen_at_OneNeck.com
> Cc: 'Oracle-L_at_freelists.org'
> Subject: RE: what could cause a high elap value for the exec system call (for a select statement)?
>
> Tim,
>
> I probably need some coffee, but below is an extract of the trace file for a select statement with a group by and a having clause:
>
> =====================
> PARSING IN CURSOR #3 len=62 dep=0 uid=0 oct=3 lid=0 tim=1227795558301877 hv=3632556357 ad='2cef325c'
> select veld1 from fdh.test2 group by veld1 having count(*) > 1
> END OF STMT
> PARSE #3:c=3000,e=3570,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1227795558301766
> EXEC #3:c=0,e=148,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1227795558303089
> WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1227795558303534
> WAIT #3: nam='db file sequential read' ela= 60 file#=5 block#=1699 blocks=1 obj#=64322 tim=1227795558305708
> WAIT #3: nam='db file scattered read' ela= 260 file#=5 block#=1700 blocks=5 obj#=64322 tim=1227795558306677
> WAIT #3: nam='db file scattered read' ela= 112 file#=5 block#=1705 blocks=8 obj#=64322 tim=1227795558308098
> WAIT #3: nam='db file scattered read' ela= 107 file#=5 block#=1714 blocks=7 obj#=64322 tim=1227795558308960
> WAIT #3: nam='db file scattered read' ela= 114 file#=5 block#=1721 blocks=8 obj#=64322 tim=1227795558309856
> WAIT #3: nam='db file scattered read' ela= 112 file#=5 block#=1730 blocks=7 obj#=64322 tim=1227795558310705
> WAIT #3: nam='db file scattered read' ela= 116 file#=5 block#=1737 blocks=8 obj#=64322 tim=1227795558311554
>
> ... lots more of db file scattered read
>
> WAIT #3: nam='db file scattered read' ela= 159 file#=5 block#=14589 blocks=12 obj#=64322 tim=1227795558903786
> WAIT #3: nam='db file scattered read' ela= 214 file#=5 block#=14617 blocks=16 obj#=64322 tim=1227795558904755
> WAIT #3: nam='db file scattered read' ela= 203 file#=5 block#=14649 blocks=16 obj#=64322 tim=1227795558905575
> WAIT #3: nam='SQL*Net more data to client' ela= 38 driver id=1413697536 #bytes=2144 p3=0 obj#=64322 tim=1227795558906250
> FETCH #3:c=616906,e=602931,p=8857,cr=8866,cu=0,mis=0,r=1,dep=0,og=1,tim=1227795558906963
> WAIT #3: nam='SQL*Net message from client' ela= 679 driver id=1413697536 #bytes=1 p3=0 obj#=64322 tim=1227795558908162
> FETCH #3:c=0,e=68,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1227795558908757
> WAIT #3: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=64322 tim=1227795558909221
> WAIT #3: nam='SQL*Net message from client' ela= 4207 driver id=1413697536 #bytes=1 p3=0 obj#=64322 tim=1227795558913914
> =====================
>
>
> STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FILTER (cr=8866 pr=8857 pw=0 time=602274 us)'
> STAT #3 id=2 cnt=1 pid=1 pos=1 obj=0 op='HASH GROUP BY (cr=8866 pr=8857 pw=0 time=602327 us)'
> STAT #3 id=3 cnt=26000 pid=2 pos=1 obj=64322 op='TABLE ACCESS FULL TEST2 (cr=8866 pr=8857 pw=0 time=991080 us)'
>
> Now, as the exec call is placed before the reading of the blocks from disk, then how can the time needed for the filtration be included in the e value of the exec call?
>
> Mvg,
>
> Freek D'Hooge
> Uptime
> Oracle Database Administrator
> email: freek.dhooge_at_uptime.be
> tel +32(0)3 451 23 82
> http://www.uptime.be
> disclaimer: www.uptime.be/disclaimer
>
>
> ________________________________________
> From: Tim Gorman [mailto:tim_at_evdbt.com]
> Sent: woensdag 4 november 2009 15:59
> To: D'Hooge Freek; mwf_at_rsiz.com; 'Daniel Fink'; tim_at_evdbt.com; Brandon.Allen_at_OneNeck.com
> Cc: 'Oracle-L_at_freelists.org'
> Subject: Re: what could cause a high elap value for the exec system call (for a select statement)?
>
> D'Hooge,
>
> The answer to your question is largely "yes", except I'd word it as "exec call includes all work (after parse call constructs the cursor) to construct the result set for the cursor".
>
> Rows cannot be retrieved (fetched) at the start of a GROUP BY operation or an ORDER BY operation for example, they can only be retrieved after those operations complete. If there is a HAVING clause then there is additional filtering to perform before the fetch phase can begin, etc. Whether that sorting or hashing occurs in private process memory (PGA) or in temporary segments is only a matter of elapsed time, but the EXEC phase won't complete until any such operations (as well as recursive operations in their entirety, as Cary pointed out) complete.
>
> Hope this helps...
>
> -Tim
> -----Original Message-----
> From: D'Hooge Freek [mailto:Freek.DHooge_at_uptime.be]
> Sent: Wednesday, November 4, 2009 07:07 AM
> To: mwf_at_rsiz.com, ''Daniel Fink'', tim_at_evdbt.com, Brandon.Allen_at_OneNeck.com
> Cc: 'Oracle-L_at_freelists.org'
> Subject: RE: what could cause a high elap value for the exec system call (for a select statement)?
>
> Mark, Am I correct to say that, for a select statement, the exec call includes all the work (except parsing) that needs to be done to construct the cursor and that the fetch call includes all the work that needs to be done to retrieve rows from that cursor? Regards, Freek D'Hooge Uptime Oracle Database Administrator email: freek.dhooge_at_uptime.be tel +32(0)3 451 23 82 http://www.uptime.be disclaimer: www.uptime.be/disclaimer -----Original Message----- From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce@freelists.org] On Behalf Of Mark W. Farnham Sent: woensdag 4 november 2009 14:47 To: D'Hooge Freek; 'Daniel Fink'; tim@evdbt.com; Brandon.Allen@OneNeck.com Cc: 'Oracle-L@freelists.org' Subject: RE: what could cause a high elap value for the exec system call (for a select statement)? I'm pretty sure Tim meant that in the context a whole heck of a lotta work must occur before you know what the first row to return is. Another example is if you have a union (non-all) and t
 he
> source datasets of the parts of the union don't have a provable joint subkey, then you have to do full projection of all the columns in the parts of the queries and sort the resultset for duplicate rejection before you return anything. Something like that with 1000 columns in the select list would be a really bad joke to play on a computer system. Please do correct me if I got that wrong, Tim. mwf
> --
> http://www.freelists.org/webpage/oracle-l
>
>
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Wed Nov 04 2009 - 14:42:25 CST

Original text of this message