Archive

Posts Tagged ‘“session cached cursor”’

Bind peeking and session cached cursor

January 30, 2015 1 comment

Bind peeking is a nice feature in Oracle to have many optimized plans for an SQL for various bind values.  DBAs believe that bind peeking happens during a soft parse which will identify an alternate plan. Why do I say that?

 

Hard Parse: Parsing first time, nothing exists to bind peek

 

Soft Parse :  SQL cursor is existing and executing not the first time.  Under the soft parse, bind peeking will happen and the new  plan will be generated based on the selectivity for that literal.

 

Session Cached cursor (Softer Soft Parse):   Cursor is existing in the PGA, bind the new value and just execute.  This is the optimal way of an SQL execution – parse once and execute many.  Less CPU, less or no latches – just bind and execute.

 

Question for the session cached cursor – since there is no soft parsing , can bind peeking happen to a session cached cursor?  Can binding will force a ‘bind peeking’ and force for soft parse if the bind value is not safe?  I asked this question to an industry expert and he believes that a session cached cursor can never do bind peeking – it will just bind and execute.  But, that is a dangerous situation as it can produce inefficient plans just because it is executing a cached SQL.

 

So, let me test it!

 

My test table ABC got 117455 rows for OBJECT_ID=2 and just one row for OBJECT_ID=1 with an index on OBJECT_ID.  For the bind peeking  test, 10046 trace shows me two different plans for OBJECT_ID=1 and 2 – one is full table scan while other is index scan.

 

The test SQL is,

 


select count(OBJECT_TYPE) from abc where object_id=:oid ;

 

With object_id=1

 


PARSING IN CURSOR #47782675682600 len=56 dep=0 uid=70 oct=3 lid=70 tim=1421932643763296 hv=3165798175 ad='1f7dd8570' sqlid='99pd5nyyb4gsz'

select count(OBJECT_TYPE) from abc where object_id=:oid

END OF STMT

PARSE #47782675682600:c=0,e=440,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1421932643763295

BINDS #47782675682600:

 Bind#0

  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0

  kxsbbbfp=2b7545793550  bln=22  avl=02  flg=05

  value=1

EXEC #47782675682600:c=1000,e=1336,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2627152604,tim=1421932643764692

WAIT #47782675682600: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643764734

FETCH #47782675682600:c=0,e=54,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2627152604,tim=1421932643764817

STAT #47782675682600 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=4 pr=0 pw=0 time=63 us)'

STAT #47782675682600 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=43 us cost=4 size=11 card=1)'

STAT #47782675682600 id=3 cnt=1 pid=2 pos=1 obj=20551 op='INDEX RANGE SCAN I_OBJECT_ID (cr=3 pr=0 pw=0 time=33 us cost=3 size=0 card=1)'

WAIT #47782675682600: nam='SQL*Net message from client' ela= 220 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765178

FETCH #47782675682600:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2627152604,tim=1421932643765213

WAIT #47782675682600: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765253

WAIT #47782675682600: nam='SQL*Net message from client' ela= 219 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932643765489

*** SESSION ID:(2299.43369) 2015-01-22 07:17:23.767

 

And with OBJECT_ID=2, is a FULL table scan


PARSING IN CURSOR #47782683021480 len=57 dep=0 uid=70 oct=3 lid=70 tim=1421932662564677 hv=860935858 ad='2353e0480' sqlid='am229vwtp1ppk'

 select count(OBJECT_TYPE) from abc where object_id=:oid

END OF STMT

PARSE #47782683021480:c=0,e=374,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1421932662564676

BINDS #47782683021480:

 Bind#0

  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00

  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0

  kxsbbbfp=2b75455c03a0  bln=22  avl=02  flg=05

  value=2

EXEC #47782683021480:c=1000,e=1225,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1045519631,tim=1421932662565992

WAIT #47782683021480: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662566033

FETCH #47782683021480:c=20996,e=21498,p=0,cr=1590,cu=0,mis=0,r=1,dep=0,og=1,plh=1045519631,tim=1421932662587561

STAT #47782683021480 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1590 pr=0 pw=0 time=21489 us)'

STAT #47782683021480 id=2 cnt=117455 pid=1 pos=1 obj=20550 op='TABLE ACCESS FULL ABC (cr=1590 pr=0 pw=0 time=27469 us cost=447 size=1305040 card=118640)'

WAIT #47782683021480: nam='SQL*Net message from client' ela= 252 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588004

FETCH #47782683021480:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1045519631,tim=1421932662588047

WAIT #47782683021480: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588069

WAIT #47782683021480: nam='SQL*Net message from client' ela= 379 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1421932662588485

*** SESSION ID:(2299.43369) 2015-01-22 07:17:42.589

 

 

Then I executed the below SQL, to see the behavior –


ALTER SESSION SET events '10046 trace name context forever, level 12';

VARIABLE oid NUMBER;

EXECUTE :oid  := 1;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

 

Looking at the cursor closing type=3 shows that, the cursor closing with caching and that is the expected behavior.


$: grep 47370175687784 xxxx_ora_10255.trc | grep type

CLOSE #47370175687784:c=0,e=15,dep=0,type=1,tim=1421938140372548

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140493515

CLOSE #47370175687784:c=0,e=13,dep=0,type=3,tim=1421938140509940

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140560694

CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140584517

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140593613

CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140681558

CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140788580

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140793258

CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140797589

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140815194

CLOSE #47370175687784:c=0,e=12,dep=0,type=3,tim=1421938140866576

CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140890609

CLOSE #47370175687784:c=0,e=11,dep=0,type=3,tim=1421938140901529

CLOSE #47370175687784:c=0,e=10,dep=0,type=3,tim=1421938140914521

CLOSE #47370175687784:c=0,e=8,dep=0,type=0,tim=1421938145465058

Here are the various values for TYPE while closing the cursor.

 

  • type 0 : Cursor is closed and not added to the session cache
  • type 1 : Cursor is closed but added to the session cache without flushing out an existing cursor
  • type 2 : Cursor is closed but added to the session cache after flushing out an existing cursor in cache
  • type 3 : Cursor is already existing in the cache

 

Now, let us see what will happen when we execute the below statement –


ALTER SESSION SET events '10046 trace name context forever, level 12';

VARIABLE oid NUMBER;

EXECUTE :oid  := 1;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

EXECUTE :oid  := 2;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

EXECUTE :oid  := 1;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

select count(OBJECT_TYPE) from abc where object_id=:oid ;

 

First 5 times, execute with a bind value 1 which will cache Indexed read plan cursor in the session cache and switch the bind to 2 which will do a full table scan if it is doing a bind peeking.  If bind peeking is not happening, it will end up with a wrong plan.  Looking at the trace files


$ :  grep  obj=20550  xxxxxx_ora_15962.trc

STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=57 us cost=4 size=11 card=1)'

STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=39 us cost=4 size=11 card=1)'

STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=39 us cost=4 size=11 card=1)'

STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=36 us cost=4 size=11 card=1)'

STAT #48000122322616 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=40 us cost=4 size=11 card=1)'



STAT #48000122321672 id=2 cnt=1879295 pid=1 pos=1 obj=20550 op='TABLE ACCESS FULL ABC (cr=24667 pr=0 pw=0 time=226535 us cost=6907 size=20702825 card=117455)'



STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=12 us cost=4 size=11 card=1)'

STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=15 us cost=4 size=11 card=1)'

STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=36 us cost=4 size=11 card=1)'

STAT #48000122321672 id=2 cnt=1 pid=1 pos=1 obj=20550 op='TABLE ACCESS BY INDEX ROWID ABC (cr=4 pr=0 pw=0 time=13 us cost=4 size=11 card=1)'

 

Interesting, bind peeking is happening for a session cached SQL!   If you look closely SQL started with a cursor ID 48000122322616 for the initial index read and closed that session cached cursor and opened a new cursor 48000122321672 for FULL table scan.  However, when the bind value change back to 1, plan got changed under the same cursor ID.  I assume this is because, both plans were cached under the same cursor, so that a session cached cursor was able to execute both plans under the same cursor ID.  Oracle is doing a great job here and avoiding sub-optimal plans for a session cached cursor.  But an unanswered question is, how Oracle was able to do bind peeking under ‘softer soft parse’.