RE: what could cause a high elap value for the exec system call (for a select statement)?
Date: Wed, 4 Nov 2009 16:33:44 +0100
Message-ID: <4814386347E41145AAE79139EAA398980D33E9FC48_at_ws03-exch07.iconos.be>
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=1227795558906250FETCH #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 the 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-lReceived on Wed Nov 04 2009 - 09:33:44 CST