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: "tim@xxxxxxxxx" <tim@xxxxxxxxx>, "ric.van.dyke@xxxxxxxxxx" <ric.van.dyke@xxxxxxxxxx>
  • Date: Wed, 4 Nov 2009 23:19:01 +0100

Hi,

First of all, many thanks to everyone who has spend time to help me figger this 
one out.
I have now a much better understanding of what is going on during the execute 
and fetch calls.

The execute call took arround 4 seconds, which includes the e values of the 
recursive statements made for this statement (I should have known this one, as 
I do have your book Cary).
The sum of these values was however only 1.5 ms, so these seem not to be the 
cause of the problem.

There are no "group by", "order by" or "for update of" clauses in the 
statement. So these could not be the cause of it either.

Allen Brandon had already send me a reply yesterday, pointing to a metalink 
article which has a (simplified) schema of what happens during the parse, exec 
and fetch stages. He also pointed out that, when bind variable peeking occurs, 
the optimization occurs in the exec phase instead of during the parse phase. 
For some reason (lack of coffee) this information did not reach my brain until 
he send me a reminder mail.
As Ric van Dyke pointed out, the statement caused a hard parse. Which means 
that the cbo would have done some bind variable peeking.

A quick test confirmed this:

With bind variables (hard parsing):
----------------------------------

PARSING IN CURSOR #3 len=53186 dep=0 uid=28 oct=3 lid=0 tim=1227900734415096 
hv=3380547863 ad='3d6c3cb0'
select /* the first one */ unitfacili0_.gkey as gkey217_0_, unit1_.gkey as 
gkey211_1_,
....
END OF STMT
PARSE #3:c=15998,e=15810,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1227900734415091
...
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=2a974b92c0  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=00 csi=00 siz=0 off=24
  kxsbbbfp=2a974b92d8  bln=22  avl=05  flg=01
  value=62012578
EXEC 
#3:c=3930402,e=3843860,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1227900738262467

Without bind variables (hard parsing):
-------------------------------------

PARSING IN CURSOR #3 len=53185 dep=0 uid=28 oct=3 lid=0 tim=1227901174488209 
hv=1358467410 ad='3d29a560'
select /* the third one */ unitfacili0_.gkey as gkey217_0_, unit1_.gkey as 
gkey211_1_,
....
END OF STMT
PARSE 
#3:c=3988394,e=3900653,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1227901174488199
BINDS #3:
EXEC #3:c=0,e=808,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1227901174492478


As you can see, the main time needed has shifted from the exec phase to the 
parse phase.
Subsequent tests also proved that when the statement was found in the shared 
pool, both the exec and parse times where back to normal:

PARSING IN CURSOR #3 len=53186 dep=0 uid=28 oct=3 lid=0 tim=1227900874172949 
hv=3380547863 ad='3d6c3cb0'
select /* the first one */ unitfacili0_.gkey as gkey217_0_, unit1_.gkey as 
gkey211_1_,
...
END OF STMT
PARSE #3:c=1999,e=1362,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1227900874172945
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=2a97332ed0  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=00 csi=00 siz=0 off=24
  kxsbbbfp=2a97332ee8  bln=22  avl=05  flg=01
  value=62012578
EXEC #3:c=1999,e=1115,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1227900874177605


So, the conclusion is that the high exec time was caused by the optimalization 
phase, which was reported in the exec phase instead of the parse phase due to 
the bind variable peeking.
The reason that the optimalization phase took such a long time could be the 
sheer length and complexity of the statement or its extensive use of ansi joins 
(or a combination of the above).
Setting the _optimizer_max_permutations parameter did not change the time 
required.

Again, many thanks to all of you.



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


Other related posts: