Kerry Osborne's Oracle Blog

I seem to have spent a lot of time during the last week having conversations about why Oracle is not locking plans, even when an Outline or SQL Profile has been created. I mean, their whole purpose in life is to keep the optimizer from changing plans, right? Here’s a bit of an email I sent with my thoughts on the issue during a conversation on the Oracle-L list.

First, I think you need to convince yourself as to whether the profile is being used or not. There is a column in v$sql (sql_profile) which will have the name of the profile if one is being used. Also xplan will show that a profile is being used at the bottom of the output.

If the profile is being used, but the plan is not what you expected, there are a couple of likely culprits.

First, if it’s a profile generated by SQL Tuning Advisor it’s quite possible that it will have one or more OPT_ESTIMATE hints – which apply scaling factors to various operations. These types of profiles can and do switch plans fairly easily, because they are not even attempting to lock anything. As the stats change, the plans can change.

The second common possibility is that Oracle decided to use an index hint that doesn’t specify the index name, but rather the columns that it would like to use an index on. For example:

INDEX_RS_ASC(@”SEL$1″ “TEST_TABLE”@”SEL$1” (“TEST_TABLE”.”COL2″ “TEST_TABLE”.”TEST_TABLE_ID”))

This hint does not specify an index, but rather columns to use an index on. I’m not sure when this form became a preferred approach but it certainly seems to show up pretty often. So that leaves the optimizer with the flexibility to pick an index based on stats. In systems with lots of indexes, this makes it more likely that a statement will switch plans even though it’s using an Outline or Profile. In fact, you may have a statement with multiple plans in the shared pool, pick one to create an Outline or Profile with, enable it, and have the new child use a plan that’s different from the plan of the child you used to create it with. Very frustrating.

So as I said in the email, the most likely cause for SQL Profiles not working is the non-specific form of index hints that are being used. However, as I was doing some research for this post, I found a couple situations where SQL Profiles just flat don’t work as advertised. I’ll show you an example, but first here are a few scripts that I will use (I sometimes don’t set “echo on” because it makes the examples so messy – so just hit the links to view the scripts):

Updated: 6/14/13
Note that I have rewritten the create_sql_profile.sql script so that it is not dependent on the rg_sqlprof1 script and to add additional functionality. Please use the newer one. Also I have rewritten the sql_profile_hints.sql script so that it works with 10g and 11g. I have disabled the links to the old versions in the list below.

sql_hints.sql – shows the hints stored in the v$sql_plan.other_xml column
sql_profile_hints.sql – shows the hints associated with a SQL Profile
sql_profile_hints11.sql – shows the hints associated with a SQL Profile (for 11g)
create_sql_profile.sql – creates a profile for a statement in the shared pool (wrapper for rg_sqlprof1.sql)
rg_sqlprof1.sql – does the real work to create a profile for a statement in the shared pool
fix_sql_profile_hint.sql – replaces a hint in a profile with whatever you want

Here’s the set up: a simple single table query that wants to do a full table scan and a second version that uses a hint to force an index. A profile created on the hinted statement should keep it from changing, but instead, it changes the plan back to a full table scan. Here’s the example:

Continue reading ‘Why Isn’t Oracle Using My Outline / Profile / Baseline?’ »

One of the old tricks with Outlines was to switch hints between two statements. This allowed hints to be applied to a statement to influence the plan that the optimizer chose. The original statement (without the hints) could then be made to behave by swapping the Outlines. It was always a questionable approach in my mind. However, DBMS_SQLTUNE has a built-in procedure to import hints into a SQL Profile which makes it feel a little less risky. So here’s a quick little script to do the old “Outline Switcheroo Trick”, but with SQL Profiles. It’s based on some work done a few months back by myself and Randolf Geist. Here’s a couple of posts to look at for background info:

• Mine
• Randolf’s

This iteration has a couple of new scripts:

create_sql_profile2.sql – creates a profile for one statement based on hints from another (wrapper for rg_profile_hints3.sql)
rg_sqlprof3.sql – modified version of Randolf’s original script, pulls hints from v$sql_plan
sql_profile_hints.sql – shows the hints in a SQL Profile for 10g

NOTE: I have posted an update to this approach here:

How to Attach a SQL Profile to a Different Statement – Take 2

You may want to skip the example below and refer to it instead (don’t miss the caveats at the bottom of this post though).

Here’s an example:

> sqlplus "/ as sysdba"

SQL*Plus: Release 10.2.0.3.0 - Production on Tue Jul 28 15:38:22 2009

Copyright (c) 1982, 2006, Oracle.  All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> @flush_pool

System altered.

Elapsed: 00:00:00.31
SQL> set echo on
SQL> set timing on
SQL> @avgskewi
SQL> select avg(pk_col) from kso.skew
  2  where col1 = 23489
  3  /

AVG(PK_COL)
-----------


Elapsed: 00:00:00.01
SQL> @avgskewi_hint
SQL> select /*+ full(skew) */ avg(pk_col) from kso.skew
  2  where col1 = 23489
  3  /

AVG(PK_COL)
-----------


Elapsed: 00:00:11.23
SQL> set timing off
SQL> @find_sql
SQL> select sql_id, child_number, plan_hash_value plan_hash, executions execs,
  2  (elapsed_time/1000000)/decode(nvl(executions,0),0,1,executions) avg_etime,
  3  buffer_gets/decode(nvl(executions,0),0,1,executions) avg_lio,
  4  sql_text
  5  from v$sql s
  6  where upper(sql_text) like upper(nvl('&sql_text',sql_text))
  7  and sql_text not like '%from v$sql where sql_text like nvl(%'
  8  and sql_id like nvl('&sql_id',sql_id)
  9  order by 1, 2, 3
 10  /
Enter value for sql_text: %skew%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
7s0b9ygcrj77u      0 3723858078          1           .01          134 select avg(pk_col) from kso.skew where col1 = 23489
9r9wq9xqsw6mu      0  568322376          1         10.97      173,731 select /*+ full(skew) */ avg(pk_col) from kso.skew where col
                                                                      1 = 23489

SQL> @dplan
SQL> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','typical'))
  2  /
Enter value for sql_id: 7s0b9ygcrj77u
Enter value for child_no: 

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  7s0b9ygcrj77u, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 23489

Plan hash value: 3723858078

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |    53 (100)|          |
|   1 |  SORT AGGREGATE              |           |     1 |    11 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| SKEW      |    54 |   594 |    53   (2)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | SKEW_COL1 |    54 |       |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("COL1"=23489)


20 rows selected.

SQL> @dplan
SQL> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','typical'))
  2  /
Enter value for sql_id: 9r9wq9xqsw6mu
Enter value for child_no: 

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  9r9wq9xqsw6mu, child number 0
-------------------------------------
select /*+ full(skew) */ avg(pk_col) from kso.skew where col1 = 23489

Plan hash value: 568322376

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       | 31719 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |
|*  2 |   TABLE ACCESS FULL| SKEW |    54 |   594 | 31719  (37)| 00:00:43 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("COL1"=23489)


19 rows selected.

SQL> -- so one statement hinted to use full table scan the other not hinted is using an index 
SQL> -- let's try creating a profile from the hinted version and putting it on none hinted statement
SQL> set echo off
SQL> @create_sql_profile2
Enter value for sql_id to generate profile from: 9r9wq9xqsw6mu
Enter value for child_no to generate profile from: 0
Enter value for sql_id to attach profile to: 7s0b9ygcrj77u
Enter value for child_no to attach profile to: 0
Enter value for category: 
Enter value for force_matching: 

PL/SQL procedure successfully completed.

SQL> @sql_profiles
Enter value for sql_text: %skew%
Enter value for name: 

NAME                           CATEGORY        STATUS   SQL_TEXT                                                               FOR
------------------------------ --------------- -------- ---------------------------------------------------------------------- ---
PROFILE_922pr090z0bvm          DEFAULT         ENABLED  select sql_id, dbms_lob.substr(sql_text,3999,1) sql_text from dba_hist NO
PROFILE_7s0b9ygcrj77u_attach   DEFAULT         ENABLED  select avg(pk_col) from kso.skew                                       NO

SQL> @sql_profile_hints
Enter value for profile_name: PROFILE_7s0b9ygcrj77u

HINT
------------------------------------------------------------------------------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('10.2.0.3')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "SKEW"@"SEL$1")

SQL> @flush_pool

System altered.

SQL> @avgskewi

AVG(PK_COL)
-----------


SQL> @find_sql
Enter value for sql_text: %skew%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
7s0b9ygcrj77u      0  568322376          1         10.29      174,071 select avg(pk_col) from kso.skew where col1 = 23489

SQL> @dplan
Enter value for sql_id: 7s0b9ygcrj77u
Enter value for child_no: 

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  7s0b9ygcrj77u, child number 0
-------------------------------------
select avg(pk_col) from kso.skew where col1 = 23489

Plan hash value: 568322376

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       | 31719 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    11 |            |          |
|*  2 |   TABLE ACCESS FULL| SKEW |    54 |   594 | 31719  (37)| 00:00:43 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("COL1"=23489)

Note
-----
   - SQL profile "PROFILE_7s0b9ygcrj77u" used for this statement


23 rows selected.

SQL> -- so this worked, statement is now using a profile generated from hints on another statement

A couple of notes:

• Beware of table aliases as they can cause hints to fail.
• Beware of any structural changes as they can cause hints to fail.
• Beware of the non-specific format of the INDEX hint.
  (it leaves the optimizer with a lot of flexibility than you probably want it to have)
  (for more details, see this post: Why Isn’t Oracle Using My Outline / Profile / Baseline?

Your comments are always welcomed.

Here’s a nifty little script that one of my co-workers (Jack Augustin) wrote to speed up the process of building test scripts. I thought it was a great idea, but of course I can never leave well enough alone, so I had to modify it slightly to my own taste (which by the way, I hope you will do as well). Anyway, the reason for the script is that we often get requests to improve a SQL statement that uses bind variables (sometimes lots of them). It’s pretty common to build a test script that can be run in SQL*Plus by grabbing the sql text and the values of the bind variables from the shared pool. Building the script though can be very tedious if the statements are long and particularly if there are a lot of bind variables. So this script eliminates most of that tedious work by generating a first cut at a test script based on a sql_id. The test script defines the variables, sets the values of the variables, and then executes the sql statement. A little manual editing may still be necessary, but it saves a lot of time.

Jack’s original version used V$SQL_BIND_CAPTURE to get bind variable values. I changed it to use the OTHER_XML column of V$SQL_PLAN. There are a few differences in these approaches.

• v$sql_plan has the values used when the statement was parsed.
• v$sql_plan usually has more bind variables in cases where there are a large number of bind variables. This is due to the fact that v$sql_bind_capture is controlled by _bind_capture_area_size which defaults to a value that is quite a bit smaller than the area used by v$sql_plan (thus a smaller number of bind variables).
• v$sql_bind_capture has the data type, v$sql_plan does not. (it’s got a numeric code for the data type – 1 for varchar2, 2 for number, etc…)

I called the script build_bind_vars.sql.

Well I was feeling all good about my version since it worked better on statements with lots of bind variables. But last week I was working on a system where they had turned off bind variable peeking via the _OPTIM_PEEK_USER_BINDS parameter. Thus, no bind info in the OTHER_XML field. Rats! Back to V$SQL_BIND_CAPTURE. So I made a copy of the script but changed it to get the values from V$SQL_BIND_CAPTURE.

Naturally I called this one build_bind_vars2.sql.

Note: these scripts depend on a little function called display_raw which I got from Greg Rahn. Here’s a script to create the function: create_display_raw.sql

UPDATED 01-JAN-13:

I have used this script a lot over the last several years and have modified it quite a bit. Here’s a newer version that is a little more functional (I also shortened the name to bbv.sql as I tend to do with scripts I use fairly often): bbv.sql

Now here’s an example:

> !sql
sqlplus "/ as sysdba"

SQL*Plus: Release 10.2.0.4.0 - Production on Thu Jul 23 08:51:53 2009

Copyright (c) 1982, 2007, Oracle.  All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> @find_sql
Enter value for sql_text: select%:4%:5%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
3hcvdhu22mjqu      0 1890474001          1           .01           76 select box_id from rule_set_rop$ where rs_obj# = :1 and ec_o
                                                                      bj# = :2  and rule_id = :3 and rule_or_piece = :4 and rop_id
                                                                       = :5 order by eval_id

57antna43jh0a      0 3630768429          1           .04          252 select box_id, value from rule_set_iot$ where rs_obj# = :1 a
                                                                      nd ec_obj# = :2  and rule_id = :3 and rule_or_piece = :4 and
                                                                       rop_id <> :5 order by rop_id
...

SQL> @build_bind_vars
Enter SQL ID ==> 3hcvdhu22mjqu
Enter Child Number ==> 0

variable N1 NUMBER
variable N2 NUMBER
variable N3 NUMBER
variable N4 NUMBER
variable N5 NUMBER

begin

end;

/

select /* test 3hcvdhu22mjqu */ box_id from rule_set_rop$ where rs_obj# = :N1 and ec_obj# = :N2  and rule_id = :N3 and rule_or_piece = :N4
and rop_id = :N5 order by eval_id;

SQL> -- Oops, nothing in the section setting the variable values!
SQL> -- Let's see what's actually in the OTHER_XML field
SQL> SQL> select other_xml from v$sql_plan
  2  where sql_id = '3hcvdhu22mjqu'          
  3  and other_xml is not null
  4  /
 
OTHER_XML
--------------------------------------------------------------------------------
10.2.0.34025366187



1 row selected.

SQL> -- Ah, no bind data in the OTHER_XML column, we'll have to get values from v$sql_bind_capture
SQL> @build_bind_vars2
Enter SQL ID ==> 3hcvdhu22mjqu
Enter Child Number ==> 

variable N1 NUMBER
variable N2 NUMBER
variable N3 NUMBER
variable N4 NUMBER
variable N5 NUMBER

begin

:N1 := 8809;
:N2 := 8794;
:N3 := 0;
:N4 := 0;
:N5 := 0;

end;

/

select /* test 3hcvdhu22mjqu */ box_id from rule_set_rop$ where rs_obj# = :N1 and ec_obj# = :N2  and rule_id = :N3 and rule_or_piece = :N4
and rop_id = :N5 order by eval_id;

SQL> -- OK, let's try executing the script
SQL> @3hcvdhu22mjqu

PL/SQL procedure successfully completed.


no rows selected

SQL> -- Well it looks like it worked, let's see if we can find the test statement
SQL> @find_sql
Enter value for sql_text: %test 3hcvdhu22mjqu%
Enter value for sql_id: 

SQL_ID         CHILD  PLAN_HASH      EXECS     AVG_ETIME      AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ ------------------------------------------------------------
7ndfkkg214gd1      0 4025366187          1           .01           85 select /* test 3hcvdhu22mjqu */ box_id from rule_set_rop$ wh
                                                                      ere rs_obj# = :N1 and ec_obj# = :N2  and rule_id = :N3 and r
                                                                      ule_or_piece = :N4 and rop_id = :N5 order by eval_id


1 row selected.

I have been using this script a lot recently. Seems like I could keep adding things to it, but it does the job for the most part. (I still need to edit the output file occasionally to clean up split words, etc…) Also, the data type mapping is not complete in build_bind_vars2.sql, it just has types 1 and 2. Most likely I won’t get around to adding other types until I actually need them. So anyway, there it is. Let me know if you have any ideas for improving it.

Here’s another interesting piece of SQL that I ran into last week:

select con_id from xyz_blah where con_id=’BS-002342′;

Actually there was a whole set of them with different literals. My first thought was, “Why would the developers want to select the con_id when they already had the con_id?”, quickly followed by “Ohhhhhhhh, it’s one of those deals where the developers didn’t trust the database or don’t know how to check for an error after executing a SQL statement”.

Presumably they know that ‘BS-002342’ is a valid con_id (it looks pretty specific to me). So the app’s probably doing one of the following three bad things (listed in what I think is the most likely order).

1. Checking to make sure a record exists with that con_id before doing something (UPDATE or DELETE).
2. Checking to make sure that a record doesn’t already exist with that con_id, before doing an INSERT.
3. Checking to make sure a DELETE actually worked.

When I looked at the stats in v$sql, the queries never return any rows. So it’s probably not #1. I didn’t find any DELETEs on the table but I did find INSERT statements with matching con_id’s, so it looks like it’s the check before insert scenario (#2). There is a Primary Key on the con_id field, so the check is of course, totally unnecessary. They should have just done the insert and handled the duplicate key error if one ever happened. By the way, in the 30 days of AWR data we had available, none of these statements ever returned a row. So most likely, they never have this issue in the first place. Of course, they might also consider using a sequence to generate the key instead of having the app manufacture a 9 character key!

Anyway, this is one of a whole set of coding issues where unnecessary work is done as a standard coding practice. Like Cary Millsap always says, “the fastest way to do anything is not to do it at all”.

I saw this statement last week:

SELECT co_id, co_name, extra_object_id FROM XYZ_BLAH
WHERE co_id in (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:
11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,:22,:23,:24,:25,:26,:
27,:28,:29,:30,:31,:32,:33,:34,:35,:36,:37,:38,:39,:40,:41,:42,:
43,:44,:45,:46,:47,:48,:49,:50,:51,:52,:53,:54,:55,:56,:57,:58,:
59,:60,:61,:62,:63,:64,:65,:66,:67,:68,:69,:70,:71,:72,:73,:74,:
75,:76,:77,:78,:79,:80,:81,:82,:83,:84,:85,:86,:87,:88,:89,:90,:
91,:92,:93,:94,:95,:96,:97,:98,:99,:100,:101,:102,:103,:104,:105
,:106,:107,:108,:109,:110,:111,:112,:113,:114,:115,:116,:117,:11
8,:119,:120,:121,:122,:123,:124,:125,:126,:127,:128,:129,:130,:1
31,:132,:133,:134,:135,:136,:137,:138,:139,:140,:141,:142,:143,:
144,:145,:146,:147,:148,:149,:150,:151,:152,:153,:154,:155,:156,
:157,:158,:159,:160,:161,:162,:163,:164,:165,:166,:167,:168,:169
,:170,:171,:172,:173,:174,:175,:176,:177,:178,:179,:180,:181,:18
2,:183,:184,:185,:186,:187,:188,:189,:190,:191,:192,:193,:194,:1
95,:196,:197,:198,:199,:200,:201,:202,:203,:204,:205,:206,:207,:
208,:209,:210,:211,:212,:213,:214,:215,:216,:217,:218,:219,:220,
:221,:222,:223,:224,:225,:226,:227,:228,:229,:230,:231,:232,:233
,:234,:235,:236,:237,:238,:239,:240,:241,:242,:243,:244,:245,:24
6,:247,:248,:249,:250,:251,:252,:253,:254,:255,:256,:257,:258,:2
59,:260,:261,:262,:263,:264,:265,:266,:267,:268,:269,:270,:271,:
272,:273,:274,:275,:276,:277,:278,:279,:280,:281,:282,:283,:284,
:285,:286,:287,:288,:289,:290,:291,:292,:293,:294,:295,:296,:297
,:298,:299,:300,:301,:302,:303,:304,:305,:306,:307,:308,:309,:31
0,:311,:312,:313,:314,:315,:316,:317,:318,:319,:320,:321,:322,:3
23,:324,:325,:326,:327,:328,:329,:330,:331,:332,:333,:334,:335,:
336,:337,:338,:339,:340,:341,:342,:343,:344,:345,:346,:347,:348,
:349,:350,:351,:352,:353,:354,:355,:356,:357,:358,:359,:360,:361
,:362,:363,:364,:365,:366,:367,:368,:369,:370,:371,:372,:373,:37
4,:375,:376,:377,:378,:379,:380,:381,:382,:383,:384,:385,:386,:3
87,:388,:389,:390,:391,:392,:393,:394,:395,:396,:397,:398,:399,:
400,:401,:402,:403,:404,:405,:406,:407,:408,:409,:410,:411,:412,
:413,:414,:415,:416,:417,:418,:419,:420,:421,:422,:423,:424,:425
,:426,:427,:428,:429,:430,:431,:432,:433,:434,:435,:436,:437,:43
8,:439,:440,:441,:442,:443,:444,:445,:446,:447,:448,:449,:450,:4
51,:452,:453,:454,:455,:456,:457,:458,:459,:460,:461,:462,:463,:
464,:465,:466,:467,:468,:469,:470,:471,:472,:473,:474,:475,:476,
:477,:478,:479,:480,:481,:482,:483,:484,:485,:486,:487,:488,:489
,:490,:491,:492,:493,:494,:495,:496,:497,:498,:499,:500,:501,:50
2,:503,:504,:505,:506,:507,:508,:509,:510,:511,:512,:513,:514,:5
15,:516,:517,:518,:519,:520,:521,:522,:523,:524,:525,:526,:527,:
528,:529,:530,:531,:532,:533,:534,:535,:536,:537,:538,:539,:540,
:541,:542,:543,:544,:545,:546,:547,:548,:549,:550,:551,:552,:553
,:554,:555,:556,:557,:558,:559,:560,:561,:562,:563,:564,:565,:56
6,:567,:568,:569,:570,:571,:572,:573,:574,:575,:576,:577,:578,:5
79,:580,:581,:582,:583,:584,:585,:586,:587,:588,:589,:590,:591,:
592,:593,:594,:595,:596,:597,:598,:599,:600,:601,:602,:603,:604,
:605,:606,:607,:608,:609,:610,:611,:612,:613,:614,:615,:616,:617
,:618,:619,:620,:621,:622,:623,:624,:625,:626,:627,:628,:629,:63
0,:631,:632,:633,:634,:635,:636,:637) ORDER BY upper(co_name)
/

That’s a lot of bind variables. I wondered how big the table was.

SQL> select count(*) from xyz_blah;

  COUNT(*)
----------
       644

Ha! That’s funny. Basically get all the rows by specifying each primary key (except for 7) in a bind variable. Seems like the following would have been simpler:

SELECT co_id, co_name, extra_object_id FROM XYZ_BLAH
WHERE co_id not in (:1,:2,:3,:4,:5,:6,:7) ORDER BY upper(co_name)
/

It made me wonder how Oracle handled that many bind variables. There does appear to be some internal limit on how many the optimizer will keep up with (and that number appears to be 585). XPLAN also reports all above 585 as “Not Captured”. Actually the number keep track of appears to depend on the size. For example, if varchar2(10) variables are used as opposed to varchar2(30) variables, the number of values that Oracle keeps up with goes up significantly.

Continue reading ‘How Many Bind Variables Is Too Many?’ »

This week I got to look at a system where a new version of an application had been rolled out. I came across a SQL statement that had taken a turn for the worse in terms of its average elapsed time. It was using an index I hadn’t noticed before, so I took a look to see if the index was new (it was – apparently it was added as part of the code roll out). So I got to wondering if there were any other statements that had suffered a backward movement in performance. So I wrote this little script called whats_changed.sql. It’s the same basic idea as one I wrote about earlier here called unstable_plans.sql. Both of these scripts are based on a calculated variance. The original unstable_plans script uses variance in average elapsed times for statements with multiple plans (i.e. it shows statements that have multiple plans which exhibit a significant difference in average elapsed time between plans). The whats_changed.sql script shows statements that exhibit significant differences in average elapsed time before and after a point in time (i.e. when you rolled out new code, or added an index, etc…) A short example may explain it better than I can:

$ !sql
sqlplus / as sysdba

SQL*Plus: Release 11.1.0.7.0 - Production on Thu Jun 25 22:24:35 2009

Copyright (c) 1982, 2008, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SQL> @whats_changed
Enter Days ago: 3
Enter value for min_stddev:
Enter value for min_etime:
Enter value for faster_slower:

SQL_ID               EXECS AVG_ETIME_BEFORE AVG_ETIME_AFTER   NORM_STDDEV RESULT
------------- ------------ ---------------- --------------- ------------- ------
an9114vtxukz2           17             1.25            5.00        2.1148 Slower
803u6vwz0ah1p           29             0.04            0.18        2.1552 Slower
bvf3fxv3hatw7        2,390             0.03            0.14        2.4147 Slower
5sgs7q9pjnzg5            2             2.21            0.42        3.0130 Faster
b0zkuv9qtcvnn           48             0.16            0.85        3.1500 Slower
9ws5c6p77d384        1,852             0.57            3.30        3.3609 Slower
dy98ajwqc8s2x           15             1.32            8.34        3.7558 Slower
bkka22vb5y7t6          596             0.19            1.26        3.8804 Slower
6qfwkqgvjkn2q           12             0.51            3.60        4.2641 Slower
05xcf43d9psvm        1,197             0.02            0.14        5.4263 Slower
8wgmc9w5ubtsy          183             0.49            4.32        5.4946 Slower
fwfpuf1vfwfu2            6             0.02            0.22        5.6314 Slower
50c18dwvxq4sb          222             0.54            5.29        6.1586 Slower
aukanfjd3d8fa            3             0.88           10.00        7.3496 Slower
44bq4r5z2xrsm           54             3.13           43.39        9.0946 Slower
0az7czjdw8z7j          110             0.62            0.02       17.5933 Faster
f41agfq9qdhk6            3             0.24            8.06       22.6765 Slower

17 rows selected.

SQL> -- or to see just the slower ones
SQL>
SQL> @whats_changed
Enter Days ago: 3
Enter value for min_stddev:
Enter value for min_etime:
Enter value for faster_slower: Slower

SQL_ID               EXECS AVG_ETIME_BEFORE AVG_ETIME_AFTER   NORM_STDDEV RESULT
------------- ------------ ---------------- --------------- ------------- ------
an9114vtxukz2           17             1.25            5.00        2.1148 Slower
803u6vwz0ah1p           29             0.04            0.18        2.1552 Slower
bvf3fxv3hatw7        2,390             0.03            0.14        2.4147 Slower
b0zkuv9qtcvnn           48             0.16            0.85        3.1500 Slower
9ws5c6p77d384        1,852             0.57            3.30        3.3609 Slower
dy98ajwqc8s2x           15             1.32            8.34        3.7558 Slower
bkka22vb5y7t6          596             0.19            1.26        3.8804 Slower
6qfwkqgvjkn2q           12             0.51            3.60        4.2641 Slower
05xcf43d9psvm        1,197             0.02            0.14        5.4263 Slower
8wgmc9w5ubtsy          183             0.49            4.32        5.4946 Slower
fwfpuf1vfwfu2            6             0.02            0.22        5.6314 Slower
50c18dwvxq4sb          222             0.54            5.29        6.1586 Slower
aukanfjd3d8fa            3             0.88           10.00        7.3496 Slower
44bq4r5z2xrsm           54             3.13           43.39        9.0946 Slower
f41agfq9qdhk6            3             0.24            8.06       22.6765 Slower

15 rows selected.

A couple of comments on the script:

• The default minimum normalized standard deviation is 2. So only statements that are 2X slower were listed.
• The default minimum average elapsed time per execution is 0.1. So only statements that ran longer than 0.1 seconds were reported.
• The DAYS_AGO parameter sets a pivot point, we’ll call it the REFERENCE_TIME. The calculations are based on averages from before and after the REFERENCE_TIME.

And a brief explanation of what’s in the output:

• SQL_ID – the statement id
• EXECS – the total number of executions in the AWR tables
• AVG_ETIME_BEFORE – the average elapsed time per execution before the REFERENCE_TIME
• AVG_ETIME_AFTER – the average elapsed time per execution after the REFERENCE_TIME
• NORM_STDDEV – this is a normalized standard deviation (i.e. how many times slower/faster it is now)

So the above output indicates that only a few statements are significantly worse (avg. elapsed time 2X or greater) since our new code rollout, which occurred about 3 days ago. Statement 44bq4r5z2xrsm obviously sticks out with a new average elapsed time of 43+ seconds and about 9 times slower than before. This was the one that had picked up the new index. The rest were primarily due to increased physical i/o caused by some newly introduced statements which were doing a few million lio’s per execution and thus causing all the other statements to suffer slightly.

Let me know what you think. Your comments are always welcome.

Last week was interesting. On Monday I was on my way to lunch with a couple of co-workers (Randy Johnson and James Garner) when the SUV in front of us launched itself off of a bridge. It looked like a scene from a car chase on a movie (but without the explosions). It just launched off into the air and then disappeared from view. I’m guessing the drop was 40 or 50 feet and the SUV was doing maybe 45 or so. James was driving and he was able to pull over into a parking lot right next to the bridge. We all bailed out and went running down the steep embankment. The SUV was floating in the middle of the lake. The front end was under water but we could still see the passengers through the front windows. They looked like they were in shock. You know how time seems to slow down when adrenaline gets released in your system. Well this was definitely one of those experiences. We spent what seemed like forever trying to get their attention and to get them to roll down their windows so they could crawl out but they never moved (it was probably like 15 seconds). Then Randy says, “We gotta get them outta there” (we’re from Texas, so that’s the way we talk). And about 3 seconds later he’s ditched his shoes and wallet and phone and he’s in the water. And I’m thinking “Rats, I guess I better go help him”. Meanwhile, James has dialed 911 and is running back up to his car to get a crow bar to break the window out. So I jump in and start swimming the 50 yards or so to the vehicle, which is surprisingly hard to do in blue jeans by the way. Another couple of guys follow us into the water as well, so there are four of us altogether.

So Randy is first to the SUV and he is at the front trying to get the passengers to wake up and roll the windows down, but he doesn’t get much response from them. Meanwhile, a couple of us swim around to the back of the truck and start trying to get the hatch open. It ended up taking three of us to get it opened. Once the door was open, the water went rushing in and in a matter of about 15 seconds the whole thing was underwater. There was a very scary couple of seconds while the passengers were clambering over the seats to the back hatch and the water was rushing in. Fortunately they were able to climb towards the back and we were able to pull them both out and then pull them back to shore. Did I mention how hard it is to swim with blue jeans on?

I really believe that the passengers were in serious risk of drowning and that if Randy had not jumped in as quickly as he did they may not have made it out. They were pretty shook up. And had the vehicle sunk before we got them I think it’s unlikely they would have been able to get themselves out. We would not have been able to help as you couldn’t see 2 inches in that water. And the water was a lot deeper than I expected. After the SUV sunk we were briefly treading water above it and I never kicked anything.  Anyway, here’s what Randy looked like in my mind’s eye on Monday:

Randy Johnson – SuperDBA

I felt more like this guy (did I mention the blue jeans, hard to swim in thing):

Kerry Osborne – Swimming in Blue Jeans

So what to do after a heroic water rescue? We went to Taco Diner and had lunch on the patio. No one even asked us why we were dripping big puddles under our chairs. Then we went back to the office, got our stuff and took the rest of the day off. It was a good day!

Recently I’ve been thinking about how often we DON’T fix problems. I mean, we usually make the situation better and often in very short order. But a lot of the time we don’t really fix “the problem”. We just do something to cover it up, or make it less painful. I call it putting Band-Aids on the problem.

The Band-Aid metaphor works on several levels.

1. Band-Aids don’t actually fix the problem, they just cover it up.
2. They aren’t meant to be permanent.
3. And they don’t keep you from stabbing yourself again in another spot.
4. But they do make it less painful.
5. And they keep out germs so they keep some problems from getting worse.
6. And they are cheap (all those boxes in the picture cost less than $20 combined).

There are all kinds of special purpose Band-Aids for special applications. Like the ones that have antibiotics, butterfly bandages for closing big cuts, etc… When it comes to Oracle, my personal favorite Band-Aid is memory. Additional memory covers up a lot of sins. One of the primary design goals of the original Oracle database was to eliminate disk access. This remains a key objective today. You can think of the database as a very sophisticated disk cache. The goal for a lot of systems is to never do real time disk access (with the exception of commit processing). So it stands to reason that memory is a key component (maybe “the” key component) of most Oracle systems. And it’s relatively cheap. There is often a surplus of memory already installed that is just not being used as effectively as it could be. But even if it’s necessary to add an additional memory module to a server, this option is generally very inexpensive when compared to other potential “hardware upgrades”.

Don’t get me wrong, there are a lot of valid reasons for using Band-Aids with Oracle. I know some people that seem adamantly against applying short term fixes instead of addressing the underlying problem. But it seems to me that in certain circumstances (which seem to occur fairly often actually) Oracle Band-Aids are an appropriate response. A few of my favorites reasons for applying them are:

1. Buying time to figure out what’s really going on and how to fix it
2. Buying time until the system is decommissioned or a new version is rolled out
3. Buying time until the developers can get the real fix through change control (and as we all know, sometimes this takes a while)
4. Just decreasing the pain because it’s a packaged app that we can’t change

I do think we should be vigilant about not overdoing it though. Otherwise our databases end up like the guy in the picture below. Pretty messy and sometimes hard to even figure out what the original intent was.

Along the same lines, keep in mind that Band-Aids often leave a lot of left over trash:

Anyway, that’s my rambling for today.  Just for fun, here are a few more pictures of some unusual Band-Aids.

Feel free to let me know what you think about applying Band-Aids to Oracle systems. And what your favorite (or least favorite) Oracle Band-Aids are.

Ah, the long awaited fix for the Bind Variable Peeking problem.

Adaptive Cursor Sharing (ACS) sounds great if you say it fast. Unfortunately it doesn’t work quite as well as I had hoped (at least as of 11.1.0.7). I was really hoping that we’d never have to worry about plan instability due to bind variable peeking again, but it seems that will remain an elusive goal for a while longer.

So the goal of this post is to provide some data about how ACS works based on observations of a couple of production systems. By the way, this post assumes you already have a basic understanding of how ACS works. There are some links at the bottom of this post to other references and in particular, this post is a good basic description of ACS.

So here’s some background info:
Observations were made on a version 10.2.0.4 RAC database that was being migrated to an 11.1.0.7 RAC database. Both are on Redhat Linux and similar Dell hardware. The version 10 database had several queries which suffered from bind variable peeking issues which were addressed with Outlines (while the developers considered using literals). Also, the statements were using real bind variables, not the fake kind that result from setting the cursor_sharing parameter. We were hoping that ACS would solve the bind variable peeking problem without manual intervention (i.e. without using Outlines or SQL Profiles or Baselines to lock in a specific plan).

I have used several scripts in this post:

unstable_plans.sql – this one shows statements that have multiple plans with large variance in execution time
awr_plan_change.sql – history of how the statement plan changes over time
awr_plan_stats.sql – aggregate statement stats (like elapsed_time, lio, etc) grouped by plan
find_sql_acs.sql – A queries v$sql and shows ACS related columns
mismatch3.sql – A variation of Dion Cho’s script to display data from v$sql_shared_cursor (see his post here)

The first couple of these scripts I discussed in a previous post on Plan Instability. I also did a previous post that is a basic overview of the Bind Variable Peeking issue, if you want a little more background info.

So here’s a look at what’s going on with that newly migrated system:

SQL*Plus: Release 11.1.0.7.0 - Production on Mon May 4 19:53:00 2009

Copyright (c) 1982, 2008, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SQL> -- find statements with multiple plans with big differences in elapsed time
SQL>
SQL> @unstable_plans
Enter value for min_stddev:
Enter value for min_etime: 1

SQL_ID        SUM(EXECS)   MIN_ETIME   MAX_ETIME   NORM_STDDEV
------------- ---------- ----------- ----------- -------------
f2pz10qx59awc          2       11.75       45.31        2.0197
5mh2127hkzbtr         70        2.64       18.06        3.0272
0hur96bxr18jn         24        1.65        9.14        3.1981
76gduk3urk91d          6        9.75       57.82        3.4880
cqxkwk9hp8rpf         31        7.18       43.77        3.6015
3u2bxt4y0740a         17        0.49        4.19        4.1316
af6j2dyzawp7w         78        6.83       60.31        4.4492
2mzzy3u2rtgqx         93        4.55       34.13        4.6025
6vb3gxdfzbhuz         33        0.63        5.21        5.1502
gc69y3vv5ws31         72        0.87        7.64        5.5128
b6zcb86sub9gv          2        0.95        8.74        5.8349
6pdbja617d2g7          2        2.24       23.55        6.7132
cc7yv55yn2wzm          5        0.26        3.05        7.4533
ach69kkyac77x          5        0.23        2.65        7.5202
09xqs3yhmnnc2         82        0.31        4.47        7.5534
3zqwzanpnddt1          2        0.69        8.75        8.2026
70zr1cg7ssfkw          2        0.71        9.04        8.2487
664tcunn5nks9          3        0.36        4.83        8.7858
39f6bx40awrms          2        0.74       10.15        9.0125
5z7v0n6amf8yx        116        9.06      125.53        9.0942
3q67n6qh7tcqv          2        0.08        1.20        9.2843
30yrz0qst88mj         68        0.21        2.97        9.3903
a1mk6hw6s20an         19        0.26        3.78        9.6454
26070mzfxps8d         72        0.18        2.75       10.0027
byznf81kmwumv          2        0.75       11.45       10.0407
1fj1qcqtmgmd1          2        0.54        9.33       11.4092
fg96c4y95u3s8          2        0.49        9.18       12.6745
chxn6vwj02xj4          2        0.65       12.27       12.7001
2xg8psmr3k7vz          2        0.76       14.38       12.7429
grysxv4s2hhkb          2        0.63       12.10       12.8338
2bfs79h84xsch        148        5.65      108.87       12.9179
4qz01hjwat4u3         39        0.27        5.50       13.6528
3wj5ngbv1sa9x          2        0.40        8.70       14.7151
g68szg2ydq6dg         14        0.26        7.48       19.4587
9vt6aaf5xcmh2        381        0.67       24.90       19.9706
cs8ng5sv7jgj4          4        1.12       35.70       21.8969
12a2xbmwn5v6z          7        0.23        8.08       23.7235
d2x7g9wr30v33          4       12.45      638.60       25.4008
4ymph98r42nbj        192        0.11        4.43       26.9188
1uby0zcw55cnp          4        0.63       31.22       34.3088
4jhx8qrkzztqg         15        1.22       66.07       37.6215
7xu6y0cvs55gh         34        0.44       30.08       37.9640
6hstnb2fghg76         77        0.65       49.01       39.2329
gzwgbycgs0fx9        265        0.08        7.37       47.4965
f028rmkp3qjvq         47        0.03        1.99       48.5307
7s1nc9wa2pc4r          2        0.19       15.53       57.6592
f2tm6xrb26y51          2        0.17       14.80       61.7260
0xz1j5y313f3c        206        0.02        2.38       71.6444
3dhwvfmkjzwtv         72        1.24      154.56       87.6684
fb90nawgwx3mj         37        0.34       51.96      108.3873
b7d0d3gu5fvqp         22        0.13       33.85      137.5321
ghdy23pftj44q       1100        0.02        5.93      143.7765
7v2jtb3u02qx6         10        0.43      139.36      172.2951
fw9ntwzhygmcq         87        0.32      100.44      220.3149
gxv6umvct0xsv       4188        0.84      333.79      225.1338
6jdu11g4zzjkh         42        0.41      137.88      234.5440
2wrngntk7v0st        183        0.11       50.61      333.9597
27wha8b8s21xw       1112        0.01        7.08      408.3026
dhmvcrmgdk3sn        881        0.05       46.99      620.1920
6u4c54k36ngwf       4329        0.00        4.39      656.4506
8jt9yh7jf8tn8       4788        0.09      160.35    1,251.5684
4fy7uznh9zz27       4723        0.03       47.16    1,256.8971
2ddh1h012t8au         12        0.03       67.62    1,491.8099
fw9hrrv37hb3v          5        0.04      100.86    1,503.5361
68wg4gjb51dsh       4411        0.01       16.44    1,539.4726
7d407h5cqmv81       4202        0.00      180.63   28,768.6107

66 rows selected.

Please note that the unstable_plan.sql script is not guaranteed to find every statement that suffers from plan instability, because some of the good plans never make it into the AWR tables. This is due to the fact that AWR only grabs the “worst” statements in the various categories that AWR reports (i.e. elapsed time, cpu time, gets, reads, and executions). But you could argue that it will find the most important ones, because even when they run fast they still end up in the top of at least one category. Anyway, it’s obvious that there are many statements that are running with multiple plans with wide variances in their execution time.

So let’s look a little closer:

SQL> -- Let's check out the worst one on the list
SQL> --   first let's see how many plans have been used and how they stack up
SQL>
SQL> @awr_plan_stats
Enter value for sql_id: 7d407h5cqmv81
Enter value for snap_id:

SQL_ID        PLAN_HASH_VALUE        EXECS          ETIME    AVG_ETIME        AVG_LIO
------------- --------------- ------------ -------------- ------------ --------------
7d407h5cqmv81      4289789142          840            2.4        0.003          273.7
7d407h5cqmv81      1007536393          551          116.2        0.211       14,563.1
7d407h5cqmv81      1723168170        2,852       44,716.2       15.679      255,603.3
7d407h5cqmv81      2337118685            1          180.6      180.629    6,495,990.0

SQL> -- So the best plan was executed 840 times and took .003 seconds on average 
SQL> -- The worst one was only executed once but took 180.6 seconds and did about 6.5M lios
SQL>
SQL>  -- Now let's see if it looks like bind variable peeking - (i.e. the plan is flip-flopping)
SQL>
SQL> @awr_plan_change
Enter value for sql_id: 7d407h5cqmv81

   SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ --------------
      1732      2 22-APR-09 01.00.06.582 PM      7d407h5cqmv81      1007536393            1        1.478        5,269.0
      1733      2 22-APR-09 02.00.06.425 PM      7d407h5cqmv81                            8        1.635       14,580.0
      1734      2 22-APR-09 03.00.01.366 PM      7d407h5cqmv81                            6        0.196       14,580.0
      1734      3 22-APR-09 03.00.00.710 PM      7d407h5cqmv81      1723168170            2        8.891      228,740.5
      1735      2 22-APR-09 04.00.19.942 PM      7d407h5cqmv81      1007536393            3        0.189       14,580.0
      1736      2 22-APR-09 05.00.06.982 PM      7d407h5cqmv81                           63        0.188       14,580.0
      1736      3 22-APR-09 05.00.06.350 PM      7d407h5cqmv81      1723168170           22        9.564      236,902.3
      1737      2 22-APR-09 06.00.03.582 PM      7d407h5cqmv81      1007536393          244        0.187       14,580.0
      1737      3 22-APR-09 06.00.04.267 PM      7d407h5cqmv81      1723168170           76        9.505      236,959.9
      1738      2 22-APR-09 07.00.28.278 PM      7d407h5cqmv81      1007536393          226        0.188       14,580.0
      1738      3 22-APR-09 07.00.28.926 PM      7d407h5cqmv81      1723168170           71        9.395      240,745.0
      1739      2 22-APR-09 08.00.09.681 PM      7d407h5cqmv81                           81       11.114      253,481.2
      1739      3 22-APR-09 08.00.10.422 PM      7d407h5cqmv81                           22        9.866      249,882.3
      1740      2 22-APR-09 09.00.43.176 PM      7d407h5cqmv81                          215       13.682      256,467.0
      1740      3 22-APR-09 09.00.43.910 PM      7d407h5cqmv81                           80       12.605      252,606.0
      1741      2 22-APR-09 10.00.16.298 PM      7d407h5cqmv81                          367       20.209      256,157.1
      1741      3 22-APR-09 10.00.17.072 PM      7d407h5cqmv81                          214       15.039      257,287.3
      1742      2 22-APR-09 11.00.28.426 PM      7d407h5cqmv81                          376       17.855      257,066.5
      1742      3 22-APR-09 11.00.27.666 PM      7d407h5cqmv81                          178       13.437      255,902.4
      1743      2 23-APR-09 12.00.16.137 AM      7d407h5cqmv81                          352       18.639      257,326.6
      1743      3 23-APR-09 12.00.15.386 AM      7d407h5cqmv81                          182       13.787      258,192.2
      1744      2 23-APR-09 01.00.03.520 AM      7d407h5cqmv81                          285       16.275      256,335.3
      1744      3 23-APR-09 01.00.02.838 AM      7d407h5cqmv81                           94       13.492      258,508.9
      1745      2 23-APR-09 02.00.21.107 AM      7d407h5cqmv81                          132       14.876      258,913.5
      1745      3 23-APR-09 02.00.20.482 AM      7d407h5cqmv81                          103       13.113      256,821.0
      1750      2 23-APR-09 07.00.33.920 AM      7d407h5cqmv81      4289789142           77        0.002          267.0
      1753      2 23-APR-09 09.34.00.440 AM      7d407h5cqmv81                          278        0.001          267.0
      1754      2 23-APR-09 11.00.06.058 AM      7d407h5cqmv81                           96        0.001          267.0
      1754      3 23-APR-09 11.00.05.422 AM      7d407h5cqmv81                           42        0.000          267.0
      1755      2 23-APR-09 11.17.45.649 AM      7d407h5cqmv81                          283        0.001          267.0
      1756      2 23-APR-09 12.00.35.977 PM      7d407h5cqmv81                           62        0.000          267.0
      1894      3 29-APR-09 06.00.09.823 AM      7d407h5cqmv81                            1        0.444        2,777.0
      1900      2 29-APR-09 12.00.36.427 PM      7d407h5cqmv81      2337118685            1      180.629    6,495,990.0
      1943      3 01-MAY-09 07.00.02.507 AM      7d407h5cqmv81      4289789142            1        1.199        3,426.0

34 rows selected.

SQL> -- It does look like a typical bind variable peeking flip-flop pattern
SQL>
SQL> -- Now let's see if it's still in the shared pool and if it's bind aware
SQL>
SQL> @find_sql_acs
Enter value for sql_text:
Enter value for sql_id: 7d407h5cqmv81
Enter value for is_bind_aware:

SQL_ID         CHILD PLAN_HASH_VALUE IBS IBA ISH      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_CPU    AVG_PIO    AVG_LIO SQL_TEXT
------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ------------------------------
7d407h5cqmv81      0      4289789142 N   N   Y            2              2       0.62       0.07     315.50      1,758 SELECT COUNT(*) as total_recor
7d407h5cqmv81      1      4289789142 N   N   Y            2              2       0.03       0.01       1.00        264

SQL> -- It is in the shared pool, but it is not bind aware
SQL> 

So the previous example showed a statement that had several plans, one of which definitely had better performance characteristics. But since there was only one plan in the shared pool at the time we examined it, there is is no reason to expect that Oracle would have recognized that the statement should be bind aware. This brings up an interesting point. It does not appear that (at least as of 11.1.0.7) Oracle keeps track of bind sensitivity of a statement persistently. That is to say, if the statement gets flushed for any reason, the optimizer appears to completely forget about any analysis it has done up to that point. Thus the painful (for the user) process of discovering which sets of bind variables should go with which plan starts all over.

So here’s another statement:

SQL> -- another example from the list of unstable_plans
SQL>
SQL> @awr_plan_stats
Enter value for sql_id: 8jt9yh7jf8tn8

SQL_ID        PLAN_HASH_VALUE        EXECS          ETIME    AVG_ETIME        AVG_LIO
------------- --------------- ------------ -------------- ------------ --------------
8jt9yh7jf8tn8      1093407144        4,818          481.5        0.100        2,818.6
8jt9yh7jf8tn8      4076066623           21        3,269.3      155.679    5,901,988.0

SQL> @awr_plan_change
Enter value for sql_id: 8jt9yh7jf8tn8

   SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ --------------
      1785      3 24-APR-09 05.00.13.361 PM      8jt9yh7jf8tn8      1093407144            6        1.102        2,872.7
      1786      2 24-APR-09 06.00.02.510 PM      8jt9yh7jf8tn8                          158        0.024        2,873.0
      1786      3 24-APR-09 06.00.03.170 PM      8jt9yh7jf8tn8                          223        0.023        2,873.0
      1787      2 24-APR-09 07.00.30.171 PM      8jt9yh7jf8tn8                          749        0.020        2,873.0
      1787      3 24-APR-09 07.00.30.935 PM      8jt9yh7jf8tn8                          873        0.019        2,873.0
      1788      2 24-APR-09 08.00.03.359 PM      8jt9yh7jf8tn8                          726        0.020        2,873.9
      1788      3 24-APR-09 08.00.04.148 PM      8jt9yh7jf8tn8                          871        0.020        2,873.9
      1789      2 24-APR-09 09.00.28.203 PM      8jt9yh7jf8tn8                          373        0.016        2,874.0
      1789      3 24-APR-09 09.00.27.481 PM      8jt9yh7jf8tn8                          566        0.016        2,874.0
      1892      2 29-APR-09 04.00.02.385 AM      8jt9yh7jf8tn8                            1        2.613        3,811.0
      1894      2 29-APR-09 06.00.09.154 AM      8jt9yh7jf8tn8                            2        0.462          733.0
      1894      3 29-APR-09 06.00.09.823 AM      8jt9yh7jf8tn8                            2        1.056          847.0
      1895      2 29-APR-09 07.00.00.226 AM      8jt9yh7jf8tn8                            7        1.714        2,869.6
      1895      3 29-APR-09 07.00.00.921 AM      8jt9yh7jf8tn8                            2        0.856        1,208.0
      1896      2 29-APR-09 08.00.20.446 AM      8jt9yh7jf8tn8                            9        1.635        2,103.0
      1897      2 29-APR-09 09.00.09.367 AM      8jt9yh7jf8tn8                            2        8.179        8,529.0
      1897      3 29-APR-09 09.00.10.115 AM      8jt9yh7jf8tn8                           17        1.714        3,416.5
      1898      2 29-APR-09 10.00.43.551 AM      8jt9yh7jf8tn8                            5        2.553        2,733.2
      1898      3 29-APR-09 10.00.42.788 AM      8jt9yh7jf8tn8                            6        3.751        4,484.2
      1899      3 29-APR-09 11.00.10.447 AM      8jt9yh7jf8tn8                            7        1.742        3,284.4
      1900      3 29-APR-09 12.00.35.788 PM      8jt9yh7jf8tn8                            2        1.199          966.0
      1901      2 29-APR-09 01.00.18.515 PM      8jt9yh7jf8tn8                            8        2.345        2,409.6
      1902      3 29-APR-09 02.00.15.910 PM      8jt9yh7jf8tn8                            2        3.941        2,649.5
      1905      2 29-APR-09 05.00.02.254 PM      8jt9yh7jf8tn8                            1        0.887        1,230.0
      1918      2 30-APR-09 06.00.09.089 AM      8jt9yh7jf8tn8                            1        0.653        1,248.0
      1918      3 30-APR-09 06.00.08.403 AM      8jt9yh7jf8tn8                            2        0.421          485.5
      1919      2 30-APR-09 07.00.28.148 AM      8jt9yh7jf8tn8                            1        1.152        1,242.0
      1920      2 30-APR-09 08.00.03.733 AM      8jt9yh7jf8tn8                            4        3.273        3,200.3
      1920      3 30-APR-09 08.00.04.389 AM      8jt9yh7jf8tn8                           12        2.491        3,314.2
      1921      2 30-APR-09 09.00.10.125 AM      8jt9yh7jf8tn8                            5        3.947        3,333.4
      1921      3 30-APR-09 09.00.10.838 AM      8jt9yh7jf8tn8                            2        2.416        1,769.5
      1922      3 30-APR-09 10.00.25.754 AM      8jt9yh7jf8tn8      4076066623            2       54.237    2,291,432.5
      1923      2 30-APR-09 11.00.17.345 AM      8jt9yh7jf8tn8      1093407144            2        0.812          975.0
      1923      3 30-APR-09 11.00.18.032 AM      8jt9yh7jf8tn8      4076066623            3      134.031      933,124.3
      1924      3 30-APR-09 12.00.15.448 PM      8jt9yh7jf8tn8                            3      227.009    6,987,169.3
      1926      2 30-APR-09 02.00.11.921 PM      8jt9yh7jf8tn8      1093407144            8        0.818        1,574.5
      1926      3 30-APR-09 02.00.11.174 PM      8jt9yh7jf8tn8      4076066623            2      175.709    8,963,417.0
      1927      2 30-APR-09 03.00.24.923 PM      8jt9yh7jf8tn8      1093407144            4        1.344        1,068.8
      1927      3 30-APR-09 03.00.24.306 PM      8jt9yh7jf8tn8      4076066623            5      156.378   10,159,992.0
      1928      2 30-APR-09 04.00.30.061 PM      8jt9yh7jf8tn8      1093407144            6        0.923        1,225.8
      1928      3 30-APR-09 04.00.29.416 PM      8jt9yh7jf8tn8      4076066623            1      180.488    2,150,190.0
      1930      3 30-APR-09 06.00.37.119 PM      8jt9yh7jf8tn8                            2      180.371    8,255,881.5
      1934      3 30-APR-09 10.00.12.055 PM      8jt9yh7jf8tn8                            1      180.491    3,102,577.0
      1939      2 01-MAY-09 03.00.31.764 AM      8jt9yh7jf8tn8      1093407144           21        0.825        1,041.8
      1939      3 01-MAY-09 03.00.32.453 AM      8jt9yh7jf8tn8                            4        0.575        1,211.8
      1944      3 01-MAY-09 08.00.15.686 AM      8jt9yh7jf8tn8                            6        1.328        1,788.3
      1946      2 01-MAY-09 10.00.17.105 AM      8jt9yh7jf8tn8                            1        1.170        2,411.0
      1946      3 01-MAY-09 10.00.16.458 AM      8jt9yh7jf8tn8                            4        2.041        2,414.3
      1947      3 01-MAY-09 11.00.14.385 AM      8jt9yh7jf8tn8                           10        1.725        2,937.1
      1948      3 01-MAY-09 12.00.08.928 PM      8jt9yh7jf8tn8                            3        2.232        3,415.7
      1987      2 03-MAY-09 03.00.03.550 AM      8jt9yh7jf8tn8                            7        1.029          901.0
      1990      3 03-MAY-09 06.00.07.641 AM      8jt9yh7jf8tn8                            3        1.225        1,465.7
      1991      3 03-MAY-09 07.00.05.445 AM      8jt9yh7jf8tn8                           26        0.370          710.5
      1992      2 03-MAY-09 08.00.20.010 AM      8jt9yh7jf8tn8                            6        0.213          685.7
      1992      3 03-MAY-09 08.00.19.366 AM      8jt9yh7jf8tn8                            3        0.658          883.0
      1993      2 03-MAY-09 09.00.04.983 AM      8jt9yh7jf8tn8                            8        0.769          950.9
      1996      2 03-MAY-09 12.00.19.205 PM      8jt9yh7jf8tn8                            2        0.101          861.5
      2015      3 04-MAY-09 07.00.13.869 AM      8jt9yh7jf8tn8                            4        0.376          854.5
      2016      3 04-MAY-09 08.00.09.477 AM      8jt9yh7jf8tn8                            6        0.143          571.0
      2019      2 04-MAY-09 11.00.11.317 AM      8jt9yh7jf8tn8                           12        0.937        1,352.1
      2019      3 04-MAY-09 11.00.10.691 AM      8jt9yh7jf8tn8                           10        1.612        1,341.9
      2019      3 04-MAY-09 11.00.10.691 AM      8jt9yh7jf8tn8      4076066623            1       41.592    3,942,672.0
      2020      2 04-MAY-09 12.00.06.355 PM      8jt9yh7jf8tn8      1093407144           15        1.037        1,734.6
      2020      3 04-MAY-09 12.00.06.919 PM      8jt9yh7jf8tn8      4076066623            1      181.044    1,764,007.0
      2022      2 04-MAY-09 02.00.26.599 PM      8jt9yh7jf8tn8      1093407144            2        2.214        2,780.5

65 rows selected.

SQL> -- typical bind variable peeking pattern
SQL> -- let's look at just one node - it'll be a little more clear
SQL> l8
  8* and ss.instance_number = S.instance_number
SQL> i
  9i and s.instance_number = &inst
 10i
SQL>
SQL> /
Enter value for sql_id: 8jt9yh7jf8tn8
Enter value for inst: 3

   SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ --------------
      1785      3 24-APR-09 05.00.13.361 PM      8jt9yh7jf8tn8      1093407144            6        1.102        2,872.7
      1786      3 24-APR-09 06.00.03.170 PM      8jt9yh7jf8tn8                          223        0.023        2,873.0
      1787      3 24-APR-09 07.00.30.935 PM      8jt9yh7jf8tn8                          873        0.019        2,873.0
      1788      3 24-APR-09 08.00.04.148 PM      8jt9yh7jf8tn8                          871        0.020        2,873.9
      1789      3 24-APR-09 09.00.27.481 PM      8jt9yh7jf8tn8                          566        0.016        2,874.0
      1894      3 29-APR-09 06.00.09.823 AM      8jt9yh7jf8tn8                            2        1.056          847.0
      1895      3 29-APR-09 07.00.00.921 AM      8jt9yh7jf8tn8                            2        0.856        1,208.0
      1897      3 29-APR-09 09.00.10.115 AM      8jt9yh7jf8tn8                           17        1.714        3,416.5
      1898      3 29-APR-09 10.00.42.788 AM      8jt9yh7jf8tn8                            6        3.751        4,484.2
      1899      3 29-APR-09 11.00.10.447 AM      8jt9yh7jf8tn8                            7        1.742        3,284.4
      1900      3 29-APR-09 12.00.35.788 PM      8jt9yh7jf8tn8                            2        1.199          966.0
      1902      3 29-APR-09 02.00.15.910 PM      8jt9yh7jf8tn8                            2        3.941        2,649.5
      1918      3 30-APR-09 06.00.08.403 AM      8jt9yh7jf8tn8                            2        0.421          485.5
      1920      3 30-APR-09 08.00.04.389 AM      8jt9yh7jf8tn8                           12        2.491        3,314.2
      1921      3 30-APR-09 09.00.10.838 AM      8jt9yh7jf8tn8                            2        2.416        1,769.5
      1922      3 30-APR-09 10.00.25.754 AM      8jt9yh7jf8tn8      4076066623            2       54.237    2,291,432.5
      1923      3 30-APR-09 11.00.18.032 AM      8jt9yh7jf8tn8                            3      134.031      933,124.3
      1924      3 30-APR-09 12.00.15.448 PM      8jt9yh7jf8tn8                            3      227.009    6,987,169.3
      1926      3 30-APR-09 02.00.11.174 PM      8jt9yh7jf8tn8                            2      175.709    8,963,417.0
      1927      3 30-APR-09 03.00.24.306 PM      8jt9yh7jf8tn8                            5      156.378   10,159,992.0
      1928      3 30-APR-09 04.00.29.416 PM      8jt9yh7jf8tn8                            1      180.488    2,150,190.0
      1930      3 30-APR-09 06.00.37.119 PM      8jt9yh7jf8tn8                            2      180.371    8,255,881.5
      1934      3 30-APR-09 10.00.12.055 PM      8jt9yh7jf8tn8                            1      180.491    3,102,577.0
      1939      3 01-MAY-09 03.00.32.453 AM      8jt9yh7jf8tn8      1093407144            4        0.575        1,211.8
      1944      3 01-MAY-09 08.00.15.686 AM      8jt9yh7jf8tn8                            6        1.328        1,788.3
      1946      3 01-MAY-09 10.00.16.458 AM      8jt9yh7jf8tn8                            4        2.041        2,414.3
      1947      3 01-MAY-09 11.00.14.385 AM      8jt9yh7jf8tn8                           10        1.725        2,937.1
      1948      3 01-MAY-09 12.00.08.928 PM      8jt9yh7jf8tn8                            3        2.232        3,415.7
      1990      3 03-MAY-09 06.00.07.641 AM      8jt9yh7jf8tn8                            3        1.225        1,465.7
      1991      3 03-MAY-09 07.00.05.445 AM      8jt9yh7jf8tn8                           26        0.370          710.5
      1992      3 03-MAY-09 08.00.19.366 AM      8jt9yh7jf8tn8                            3        0.658          883.0
      2015      3 04-MAY-09 07.00.13.869 AM      8jt9yh7jf8tn8                            4        0.376          854.5
      2016      3 04-MAY-09 08.00.09.477 AM      8jt9yh7jf8tn8                            6        0.143          571.0
      2019      3 04-MAY-09 11.00.10.691 AM      8jt9yh7jf8tn8      4076066623            1       41.592    3,942,672.0
      2019      3 04-MAY-09 11.00.10.691 AM      8jt9yh7jf8tn8      1093407144           10        1.612        1,341.9
      2020      3 04-MAY-09 12.00.06.919 PM      8jt9yh7jf8tn8      4076066623            1      181.044    1,764,007.0
      2031      3 04-MAY-09 11.00.03.519 PM      8jt9yh7jf8tn8      1093407144            1        0.737          482.0
      2039      3 05-MAY-09 07.00.27.610 AM      8jt9yh7jf8tn8      4076066623            5       42.900    4,295,251.8
      2041      3 05-MAY-09 09.00.09.829 AM      8jt9yh7jf8tn8                            2        3.282    1,968,698.5
      2044      3 05-MAY-09 12.00.16.920 PM      8jt9yh7jf8tn8      1093407144            2        1.535          844.5
      2045      3 05-MAY-09 01.00.08.637 PM      8jt9yh7jf8tn8                            2        2.384        1,683.5

41 rows selected.

SQL> -- the plans are clearly flip-flopping
SQL> -- and the performance of plan 1093407144 is clearly orders of magnitude better
SQL> 
SQL> -- Let's see what's in the shared pool
SQL>
SQL> @find_sql_acs
Enter value for sql_text:
Enter value for sql_id: 8jt9yh7jf8tn8
Enter value for is_bind_aware:

SQL_ID         CHILD PLAN_HASH_VALUE IBS IBA ISH      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_CPU    AVG_PIO    AVG_LIO SQL_TEXT
------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- -----------------------------------
8jt9yh7jf8tn8      0      4076066623 N   N   Y           19              6     160.35      29.28 ##########  6,222,898 SELECT row_order, cdr_id, site_id,
8jt9yh7jf8tn8      1      1093407144 N   N   Y           61              0       1.92       0.13     565.70      2,860 SELECT row_order, cdr_id, site_id,
8jt9yh7jf8tn8      2                 N   N   Y           55              0       1.01       0.06     252.09      1,555 SELECT row_order, cdr_id, site_id,

SQL> -- So there are children with both plans in the shared the pool (135 execs total)
SQL> -- But the cursors are not marked as bind aware
SQL> -- So why are there multiple child cursors?
SQL> -- (using a modified version of Dion Cho's script)
SQL>
SQL> @mismatch3
Enter value for sql_id: 8jt9yh7jf8tn8
SQL_ID                         = 8jt9yh7jf8tn8
CHILD_NUMBER                   = 1
--------------------------------------------------
SQL_ID                         = 8jt9yh7jf8tn8
CHILD_NUMBER                   = 0
ROLL_INVALID_MISMATCH          = Y
--------------------------------------------------
SQL_ID                         = 8jt9yh7jf8tn8
CHILD_NUMBER                   = 2
ROLL_INVALID_MISMATCH          = Y
--------------------------------------------------

PL/SQL procedure successfully completed.

SQL> -- none of the bind related flags show up, so it doesn't look promising for ACS
SQL> -- 

Brief Digression: The ROLL_INVALID_MISMATCH flag has to do with changing stats using AUTO_INVALIDATE which does not cause cursors to be immediately invalidated, but instead let’s them be invalidated over a rolling window (_optimizer_invalidation_period which defaults to 5 hours).

So then I got to wondering if any statements were being marked as bind aware.

SQL> @find_sql_acs
Enter value for sql_text:
Enter value for sql_id:
Enter value for is_bind_aware: Y

SQL_ID         CHILD PLAN_HASH_VALUE IBS IBA ISH      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_CPU    AVG_PIO    AVG_LIO SQL_TEXT
------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- ---------------
0qvgb3dyfg539      1       722236007 Y   Y   Y            2              0        .15        .02      23.00      3,487 SELECT row_orde
17uuqnvxmzxhj      1      3038781757 Y   Y   Y           31             31        .17        .01      43.74      1,126 SELECT COUNT(*)
                   3      3038781757 Y   Y   N           21             21        .02        .02       1.33      7,290
                   4      3038781757 Y   Y   Y           52             52        .23        .02     120.29      2,046
                   6      3038781757 Y   Y   Y           51             51        .00        .00        .10        284
34x6683rpwtxa      4       722236007 Y   Y   Y           18            164        .01        .00        .17        498 SELECT row_orde
3tfx8fzp64vkb      1      3038781757 Y   Y   Y            2              2        .01        .01        .00      1,178 SELECT COUNT(*)
4vb86f36xqc50      1      2983410489 Y   Y   Y           62           1683        .12        .01      53.76        960 SELECT row_orde
                   4      2983410489 Y   Y   Y            7            163        .69        .07     328.43        723
58p0j1q6rmv34      1      1144901783 Y   Y   Y            2              2        .02        .00        .00        335 SELECT COUNT(*)
5mxqphz5qfs4d      1      1144901783 Y   Y   Y            2              2        .02        .00        .00         54 SELECT COUNT(*)
dt1v1cmua9cnq      1      4076066623 Y   Y   Y            8             37       3.47       3.41      15.63  2,233,144 SELECT row_orde
ftxa99d89yzz0      1      4289789142 Y   Y   Y            2              2        .01        .00        .00        157 SELECT COUNT(*)
g375mcpc30dy5      2      1690109023 Y   Y   N            1             10        .03        .01        .00        767 SELECT row_orde
                   3      1690109023 Y   Y   Y            5             24        .02        .00       2.00        362

15 rows selected.

SQL> -- 

Sure enough, there are a few (10 statements to be exact with a total of 15 child cursors) that are marked as Bind Aware. However, there are only 3 statements that have multiple child cursors (sql_id: 17uuqnvxmzxhj, 4vb86f36xqc50, g375mcpc30dy5). And for each of those statements, the child cursors all have the same plan (sql_id: 17uuqnvxmzxhj, for example, has 3 children all using plan_hash_value: 3038781757). So even though they are marked Bind Aware, and have multiple child cursors, they are not producing distinct plans for those statements. So even the ones that the optimizer has noticed, do not appear to be providing us any benefit.

But back to the original question. We have many statements that are suffering from bind variable peeking issues that are apparently not being noticed. Why is that? Well I got to thinking about why ACS might be ignoring the statements that I know have this issue. One of the characteristics of these statements is that they have a relatively large number of bind variables. Some of them have as many as a couple of hundred. So I let my mind wander off into programmer land. How would the guys writing the optimizer code deal with a situation where they had a virtually unlimited number of bind variables. My first thought was to just put a hard limit on the number of variables to handle. Histograms have a relatively small number of potential buckets, and since ACS uses a histogram approach, it stands to reason the programmers might have put in a relatively small limit for their first pass. So I went off to test this idea (since this post is already so long I’ll cut right to the chase). There does appear to be a hard limit of 14 bind variables and statements that have more than that are apparently not evaluated for bind sensitivity. Here’s a test case:

> !sql
sqlplus "/ as sysdba"

SQL*Plus: Release 11.1.0.7.0 - Production on Mon May 11 11:16:06 2009

Copyright (c) 1982, 2008, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> !cat t14.sql
set echo off
variable v1 number
variable v2 varchar2(30)
variable v3 varchar2(30)
variable v4 varchar2(30)
variable v5 varchar2(30)
variable v6 varchar2(30)
variable v7 varchar2(30)
variable v8 varchar2(30)
variable v9 varchar2(30)
variable v9 varchar2(30)
variable v10 varchar2(30)
variable v11 varchar2(30)
variable v12 varchar2(30)
variable v13 varchar2(30)
variable v14 varchar2(30)
variable v15 varchar2(30)
variable v16 varchar2(30)
variable v17 varchar2(30)
variable v18 varchar2(30)
variable v19 varchar2(30)
exec :v1 := 999999;
exec :v2 := 'TESTING'
exec :v3 := '01-jan-08'
exec :v4 := '01-jan-09'
exec :v5 := 'Y'
exec :v6 := 'X'
exec :v7 := 'y'
exec :v8 := 'Z'
exec :v9 := 'a'
exec :v10 := 'b'
exec :v10 := 'c'
exec :v11 := 'd'
exec :v12 := 'e'
exec :v13 := 'f'
exec :v14 := 'g'
exec :v15 := 'h'
exec :v16 := 'i'
exec :v17 := 'j'
exec :v18 := 'k'
exec :v19 := 'l'
set echo on
select avg(pk_col) from kso.little_skew
where col1 = :v1
and col2 = :v2
and col3 between :v3 and :v4
and col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:v11,:v12,:v13,:v14)
/

SQL> @flush_pool
SQL> @t14
SQL> @t14
SQL> @t14
SQL> @t14
SQL> 
SQL> -- 4 execs of the first bind variable set, now let's use a different set of bind variables
SQL> -- t14a.sql is the same except v1=1 - which (due to histogram) wants to use a different plan
SQL>
SQL> @t14a
SQL> @t14a
SQL> @t14a
SQL> @t14a
SQL> @t14a
SQL> @t14a
SQL> @t14a
SQL>
SQL> -- 7 execs with the new set of bind variables, should give it plenty of info to make it bind aware
SQL> -- now a few more with the original set of bind variables
SQL>
SQL> @t14
SQL> @t14
SQL> @t14
SQL> @t14
SQL>
SQL> -- now let's see what we've got
SQL>
SQL> @find_sql_acs 
Enter value for sql_text: %v14)%
Enter value for sql_id: 
Enter value for is_bind_aware: 

SQL_ID         CHILD PLAN_HASH_VALUE IBS IBA ISH      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_CPU    AVG_PIO    AVG_LIO SQL_TEXT
------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- -----------------------------------
2yk8hbkc4kbd5      0       376960484 N   N   N            8              8        .18        .18        .00      2,641 select avg(pk_col) from kso.little_
                                                                                                                       skew where col1 = :v1 and col2 = :v
                                                                                                                       2 and col3 between :v3 and :v4 and
                                                                                                                       col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:
                                                                                                                       v11,:v12,:v13,:v14)

2yk8hbkc4kbd5      1      3746388338 N   Y   Y            3              3        .00        .00        .00         15 select avg(pk_col) from kso.little_
                                                                                                                       skew where col1 = :v1 and col2 = :v
                                                                                                                       2 and col3 between :v3 and :v4 and
                                                                                                                       col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:
                                                                                                                       v11,:v12,:v13,:v14)

2yk8hbkc4kbd5      2       376960484 N   Y   Y            4              4        .00        .00        .00          3 select avg(pk_col) from kso.little_
                                                                                                                       skew where col1 = :v1 and col2 = :v
                                                                                                                       2 and col3 between :v3 and :v4 and
                                                                                                                       col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:
                                                                                                                       v11,:v12,:v13,:v14)


3 rows selected.

SQL> -- As expected, the optimizer has noticed and marked it Bind Aware
SQL> -- Now let's try the same thing with 15 bind variables instead of 14
SQL> -- (note: t15 is the same with one more bind variable)
SQL>
SQL> @t15
SQL> @t15
SQL> @t15
SQL> @t15
SQL> @t15a
SQL> @t15a
SQL> @t15a
SQL> @t15a
SQL> @t15a
SQL> @t15a
SQL> @t15a
SQL> @t15
SQL> @t15
SQL> @t15
SQL> @t15
SQL> @find_sql_acs
Enter value for sql_text: %v15)%
Enter value for sql_id: 
Enter value for is_bind_aware: 

SQL_ID         CHILD PLAN_HASH_VALUE IOB IBA ISH      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_CPU    AVG_PIO    AVG_LIO SQL_TEXT
------------- ------ --------------- --- --- --- ---------- -------------- ---------- ---------- ---------- ---------- -----------------------------------
4ndg8w1ga5dth      0       376960484 N   N   Y           15             15        .17        .16        .00      2,465 select avg(pk_col) from kso.little_
                                                                                                                       skew where col1 = :v1 and col2 = :v
                                                                                                                       2 and col3 between :v3 and :v4 and
                                                                                                                       col4 in (:v5,:v6,:v7,:v8,:v9,:v10,:
                                                                                                                       v11,:v12,:v13,:v14,:v15)


1 row selected.

SQL> -- no joy!
SQL>
SQL> -- so now I wondered if it really was just a hard limit or something more complicated
SQL> -- so I wrote a little script to count the number of bind variables in Bind Aware statements
SQL>
SQL> !cat acs_bind_count.sql
select distinct sql_id, bind_count from (
select sql_id, child_number, count(*) bind_count from v$sql_bind_capture
where sql_id in (
select sql_id from v$sqlarea where is_bind_aware = 'Y')
group by sql_id, child_number
)
order by bind_count
/

SQL> @acs_bind_count.sql

SQL_ID        BIND_COUNT
------------- ----------
2jmg3n6k2q82x          2
dxjvgtd3stafn          4
ck67mwdmdnaww          8
9pcw6qh83mj69          9
883uvnn2gz36u         10
4ysyd47nkap6d         11
7mygfqgs52au2         12
2744r65xx9h2h         13
2yk8hbkc4kbd5         14

9 rows selected.

So it looks like there probably is a hard limit. Let’s see if I can disprove that by looking at a couple of production systems. Here’s the output from the same script on four production instances (note: system 1 is that same one that I referenced earlier with the statements with known Bind Variable Peeking issues, where ACS was not noticing them):

-- System 1, Node 2

SQL> @acs_bind_count

SQL_ID        BIND_COUNT
------------- ----------
17uuqnvxmzxhj          8
58p0j1q6rmv34          8
5mxqphz5qfs4d          8
g375mcpc30dy5          8
3tfx8fzp64vkb          9
4vb86f36xqc50          9
34x6683rpwtxa         10
dt1v1cmua9cnq         11
ftxa99d89yzz0         11
0qvgb3dyfg539         12

10 rows selected.


-- System 1, Node 3

SQL> @acs_bind_count

SQL_ID        BIND_COUNT
------------- ----------
5bjg6w9btv3zn          7
17uuqnvxmzxhj          8
6n1790gk5m0hy          8
2pv7g3nutnyq5          9
4vb86f36xqc50          9
11at9nnhrw3w9         10
4p9zp29bcu927         10
4axts2hm73n98         11
ftxa99d89yzz0         11
490gh9uugyqqq         13

10 rows selected.

-- System 2, Node 1

SQL> @acs_bind_count

SQL_ID        BIND_COUNT
------------- ----------
4rqy85b9r413x          1
7h47mb48s19t3          1
51z6b0kbduf8m          2
djkchp3qwadu1          2
9g5ng8xjj4h05          3
amyvvzzjccvsg          3
cuv2pyzvz7b4z          3
d68jnfnqs6uh7          3
dkc2kbj7kdsu7          3
fxmfhkkhcrdj6          3
6196v5td8pk4n          4
9m63xcj6sbswu          4
0mn3xx02ww6pd          5
c7k3pwbjg4d1d          5
dy98ajwqc8s2x          5
3qh6yw37n8m1a          6
3xxgg248shg62          6
83v17f53rnzcv          6
a2271k4f7j211          6
06n7rk2jw3rsy          7
f4xr9x5wh46zt          7
48ryzfg5dxpqn          8
an9114vtxukz2          8

23 rows selected.

-- System 2, Node 2

SQL> @acs_bind_count

SQL_ID        BIND_COUNT
------------- ----------
4rqy85b9r413x          1
7h47mb48s19t3          1
gvj749s4654hm          1
51z6b0kbduf8m          2
6qwznvjfajh7t          2
djkchp3qwadu1          2
2mhfdtyrvhz3c          3
92a7wu0891bjk          3
9g5ng8xjj4h05          3
9p9gsakw5qyrg          3
amyvvzzjccvsg          3
bs63sfxynwtc6          3
cuv2pyzvz7b4z          3
d68jnfnqs6uh7          3
dvh3d8g2f844j          3
0341h5ytqbv7k          4
...
gj0rzh6xw2msp          4
grvh9mmkynm4u          4
0mn3xx02ww6pd          5
7ys2u732cj1ag          5
9kfj6kj32p7ku          5
dy98ajwqc8s2x          5
83v17f53rnzcv          6
d79xsp0utuvm2          6
gqkx5bsg1zfzc          6
4q3n2wwqtghma          7
f4xr9x5wh46zt          7
g7c90sr77bb78          7
7gb24h57r0spb          8
9zcy2yz537z41          8
an9114vtxukz2          8
7uwy0uxauuabz          9
80xmux45pvkrr          9

73 rows selected.

So it appears that there probably is a hard limit and that it probably is 14 (although there certainly could be a more complicated algorithm in play). None of the 4 production systems I checked had a single statement that was marked bind aware with more than 14 bind variables.

So here are a few closing thoughts:

To me, ACS doesn’t seem to be completely cooked yet. In fact, it seems to be somewhat of a futile attempt, since in the very best case, one execution with a bad plan would be necessary for the optimizer to recognize that a bind variable peeking issue existed. This wouldn’t be so bad if the information was persisted, so that the same “learning” process wouldn’t have to be endured if/when a statement gets flushed from the shared pool. This issue alone is enough to keep this feature from being relied upon in situations where performance is critical. In my opinion, the best approach remains unchanged from version 10, that being the judicious use of literals where necessary to prevent plan instability due to bind variable peeking.

My impression of it is not completely negative though. It’s certainly better than the old approach of pick a plan and stick with it. And for systems that use a limited number of binds per statement where performance swings are not as dramatic and/or performance is not as critical, it seems to work pretty well.

Here are some other references:

OptimizerMagic Blog – Good basic description of ACS
OptimizerMagic Blog – Update on ACS
Ric Van Dyke – Intelligent Cusor Sharing in 11.1.0.6
Ric Van Dyke – Intelligent Cusor Sharing in 11.1.0.7
Section on ACS in Troubleshooting Oracle Performance By Christian Antognini

I had an interesting discussion last week with an Oracle DBA that I have a lot of respect for. He surprised me by telling me that he thought development systems should intentionally be built to be slow. That way, the developers would be forced to write efficient code. He was not just stating a philosophical position either. He had actually built some databases with 32M buffer caches (the one I mentioned in this previous post on Buffer Cache Extremes was one of his). He went so far as to say that he thought that developers should be using 286’s for their development systems.

I have argued for several years that development systems should match production as closely as possible. But that conversation really got me thinking. Maybe intentionally slowing down development systems is not such a bad idea…

So what do you think?