RE: what could cause a high elap value for the exec system call (for a select statement)?
- From: "Mark W. Farnham" <mwf@xxxxxxxx>
- To: <Freek.DHooge@xxxxxxxxx>, "'Daniel Fink'" <daniel.fink@xxxxxxxxxxxxxx>, <tim@xxxxxxxxx>, <Brandon.Allen@xxxxxxxxxxx>
- Date: Wed, 4 Nov 2009 08:46:40 -0500
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
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of D'Hooge Freek
Sent: Wednesday, November 04, 2009 5:52 AM
To: Daniel Fink; tim@xxxxxxxxx; Brandon.Allen@xxxxxxxxxxx
Cc: Oracle-L@xxxxxxxxxxxxx
Subject: RE: what could cause a high elap value for the exec system call
(for a select statement)?
Hi,
Thank you for your answers.
I have not found any "order by", "group by" or "for update" clauses in the
sql statement, but there are something like 50 joins (most of which are
outer joins) and more then 1000 (!) columns in the select clause.
Yes, this statement is generated using hibernate :(
I also found several select's in the select clause, but a small test does
seem to indicate that the time spend for these statements is not added to
the exec call, but to the fetch call.
Several statements to the data dictionary are parsed and executed between
the parse and exec call of the problem statements, but these are normally
counted seperated, right? (the sum of there e values is also only arround 1
ms).
Tim,
You said that for instance a "group by" can cause a high amount of
processing befor the first row is fetched, but is reading the blocks from
disk not part of the fetch call? If so, how can the exec call then be done
before the fetch?
Can you point me to some documentation or metalink articles which explain
what is done during the exec call and the fetch call?
Below you find an extract of the raw trace file:
PARSING IN CURSOR #39 len=52062 dep=0 uid=28 oct=3 lid=28
tim=1226849063027658 hv=433704469 ad='3dfad368'
select ... where unitfacili0_.fcy_gkey=:1 and unitfacili0_.gkey=:2
END OF STMT
PARSE
#39:c=15998,e=15401,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1226849063027654
WAIT #39: nam='library cache lock' ela= 756 handle address=5359617304 lock
address=5048146120 100*mode+namespace=301 obj#=12459 tim=1226849063029308
WAIT #39: nam='library cache lock' ela= 166 handle address=5359581160 lock
address=5041062936 100*mode+namespace=301 obj#=12459 tim=1226849063029778
WAIT #39: nam='library cache lock' ela= 385 handle address=5334638072 lock
address=5037430224 100*mode+namespace=301 obj#=12459 tim=1226849063030891
WAIT #39: nam='library cache lock' ela= 1222 handle address=5355144664 lock
address=5040009304 100*mode+namespace=301 obj#=12459 tim=1226849063033345
WAIT #39: nam='library cache lock' ela= 170 handle address=5355138832 lock
address=5396012032 100*mode+namespace=301 obj#=12459 tim=1226849063033630
/* some other recurrent statements to the data dictionary... */
BINDS #39:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
kxsbbbfp=2a974d5fd0 bln=22 avl=04 flg=05
value=46948
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=2a974d5fe8 bln=22 avl=05 flg=01
value=62012578
EXEC
#39:c=4263352,e=4204874,p=0,cr=66,cu=0,mis=1,r=0,dep=0,og=1,tim=122684906723
2845
WAIT #39: nam='SQL*Net message to client' ela= 2 driver id=1413697536
#bytes=1 p3=0 obj#=12459 tim=1226849067233413
WAIT #39: nam='SQL*Net more data to client' ela= 34 driver id=1413697536
#bytes=2004 p3=0 obj#=12459 tim=1226849067233559
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=1998 p3=0 obj#=12459 tim=1226849067233656
WAIT #39: nam='SQL*Net more data to client' ela= 8 driver id=1413697536
#bytes=2002 p3=0 obj#=12459 tim=1226849067233778
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=2000 p3=0 obj#=12459 tim=1226849067233873
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=2003 p3=0 obj#=12459 tim=1226849067233968
WAIT #39: nam='SQL*Net more data to client' ela= 3 driver id=1413697536
#bytes=2010 p3=0 obj#=12459 tim=1226849067234062
WAIT #39: nam='SQL*Net more data to client' ela= 3 driver id=1413697536
#bytes=1990 p3=0 obj#=12459 tim=1226849067234154
WAIT #39: nam='SQL*Net more data to client' ela= 5 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067234244
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067234333
WAIT #39: nam='SQL*Net more data to client' ela= 5 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067234427
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=2004 p3=0 obj#=12459 tim=1226849067234516
WAIT #39: nam='SQL*Net more data to client' ela= 3 driver id=1413697536
#bytes=1998 p3=0 obj#=12459 tim=1226849067234606
WAIT #39: nam='SQL*Net more data to client' ela= 494 driver id=1413697536
#bytes=2005 p3=0 obj#=12459 tim=1226849067235186
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=1997 p3=0 obj#=12459 tim=1226849067235278
WAIT #39: nam='SQL*Net more data to client' ela= 4 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067235371
WAIT #39: nam='SQL*Net more data to client' ela= 5 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067235463
WAIT #39: nam='SQL*Net more data to client' ela= 3 driver id=1413697536
#bytes=2001 p3=0 obj#=12459 tim=1226849067235552
WAIT #39: nam='SQL*Net more data to client' ela= 1646 driver id=1413697536
#bytes=2002 p3=0 obj#=12459 tim=1226849067237283
WAIT #39: nam='SQL*Net message from client' ela= 7616 driver id=1413697536
#bytes=1 p3=0 obj#=12459 tim=1226849067262053
WAIT #39: nam='db file sequential read' ela= 2839 file#=7 block#=1077147
blocks=1 obj#=12172 tim=1226849067265635
WAIT #39: nam='SQL*Net message to client' ela= 2 driver id=1413697536
#bytes=1 p3=0 obj#=12172 tim=1226849067266388
WAIT #39: nam='SQL*Net more data to client' ela= 22 driver id=1413697536
#bytes=2001 p3=0 obj#=12172 tim=1226849067266485
FETCH
#39:c=2000,e=4451,p=1,cr=75,cu=0,mis=0,r=1,dep=0,og=1,tim=1226849067266575
WAIT #39: nam='SQL*Net message from client' ela= 90813 driver id=1413697536
#bytes=1 p3=0 obj#=12172 tim=1226849067360100
WAIT #39: nam='SQL*Net more data from client' ela= 9 driver id=1413697536
#bytes=1317 p3=0 obj#=12172 tim=1226849067360177
PART OF THE TKPROF REPORT
-------------------------
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.01 0.01 0 0 0
0
Execute 1 4.25 4.19 0 66 0
0
Fetch 1 0.00 0.00 1 75 0
1
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 3 4.27 4.21 1 141 0
1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 28
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
library cache lock 5 0.00
0.00
SQL*Net message to client 2 0.00
0.00
SQL*Net more data to client 19 0.00
0.00
SQL*Net message from client 2 0.09
0.09
db file sequential read 1 0.00
0.00
SQL*Net more data from client 1 0.00
0.00
****************************************************************************
****
Kind Regards,
Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge@xxxxxxxxx
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
