RE: what could cause a high elap value for the exec system call (for a select statement)?
- From: D'Hooge Freek <Freek.DHooge@xxxxxxxxx>
- To: Daniel Fink <daniel.fink@xxxxxxxxxxxxxx>, "tim@xxxxxxxxx" <tim@xxxxxxxxx>, "Brandon.Allen@xxxxxxxxxxx" <Brandon.Allen@xxxxxxxxxxx>
- Date: Wed, 4 Nov 2009 11:51:54 +0100
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=1226849067232845
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
--
http://www.freelists.org/webpage/oracle-l
Other related posts: