RE: what could cause a high elap value for the exec system call (for a select statement)?
Date: Wed, 4 Nov 2009 11:51:54 +0100
Message-ID: <4814386347E41145AAE79139EAA398980D33E9FBD5_at_ws03-exch07.iconos.be>
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=1226849063030891WAIT #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=05value=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=01value=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=1226849067266485FETCH #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_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
--
http://www.freelists.org/webpage/oracle-l
Received on Wed Nov 04 2009 - 04:51:54 CST