Bind Variable Peeking – execution plan inefficiency

In my Beyond Oracle Wait interface article I troubleshooted a test case where an execution plan somehow went “crazy” and started burning CPU, lots of logical IOs and the query never completed.

I have uploaded the test case I used to my new website, to a section where I will upload some of my demo scripts which I show at my seminars (and people can download & test these themselves too):

http://tech.e2sn.com/oracle-seminar-demo-scripts

Basically what I do is this:

  1. I run the query with bind variable values where only a handful of rows match the filter condition. Thus Oracle picks nested loop join (and indexed access path)
  2. Then I run the same query with different bind values, where a lot of rows match the filter condition. Oracle reuses existing execution plan (with nested loops!!!). Oracle ends up looping through a lot of blocks again and again (because nested loop visits the “right” side of the join once for every row coming from the “left” side of the join).

Using nested loops over lots of rows is a sure way to kill your performance.

And an interesting thing with my script is that the problem still happens in Oracle 11.1 and 11.2 too!

Oracle 11g has Adaptive Cursor Sharing, right? This should take care of such a problem, right? Well no, adaptive bind variable peeking is a reactive technique – it only kicks in after the problem has happened!

So feel free to download the script, review it and test it out!

This entry was posted in Oracle and tagged , , . Bookmark the permalink.

8 Responses to Bind Variable Peeking – execution plan inefficiency

  1. >Oracle 11g has Adaptive Bind Peeking, right?
    Adaptive Cursor Sharing, right :)

    >Well no, adaptive bind variable peeking is a reactive technique – it only kicks in after the problem has happened!
    Right, I’m sure you’ve read Kerry’s post on this matter.

  2. Tanel Poder says:

    @Timur Akhmadeev
    Yeah, I meant adaptive cursor sharing! I wrote the adaptive bind peeking off the top of my head.. fixed now.

    I haven’t had a chance to read much blog entries lately, but yeah I’m aware of the quality of Kerry’s stuff!

  3. The dynamics behind this situation have been a bit challenging for me to explain to developers and managers when it’s occurred in my own environments. Luckily for me, it occurs consistently enough and I can “force” a fix that they realize I’m not making it up! Excellent article and indepth research into this challenging complication with the bind variable peek feature!

  4. king4aday says:

    the solution: alter system flush shared_pool :)

  5. Boris Vayntrub says:

    So, how to avoid bad execution time firs time ? Can someone post a link to an article itself? Sorry, i am new to this blog.

  6. Boris Vayntrub says:

    I actually spent some time to run sql scripts to demonstrate this issue. What I found is that the only reason optimizer does not change a plan for second execution , when performance is bad was that “ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=10;” was issued earlier. If prior to executing script with ‘SYS’ value of a bind variable you would change it back : “ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=100′ which is a default btw, optimizer would change its plan to hash join from nested loops. So, what is an issue? Adaptive cursor does work

    SQL> DROP TABLE t1;
    DROP TABLE t2;
    DROP TABLE t3;

    CREATE TABLE t1 AS SELECT * FROM dba_objects;
    CREATE TABLE t2 AS SELECT * FROM dba_objects;
    CREATE TABLE t3 AS SELECT * FROM dba_objects;

    CREATE INDEX i1 ON t1(owner);
    CREATE INDEX i2 ON t2(owner);
    CREATE INDEX i3 ON t3(owner);

    EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T1′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);
    EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T2′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);
    EXEC DBMS_STATS.GATHER_TABLE_STATS(user,’T3′,cascade=>TRUE, method_opt=>’FOR ALL INDEXED COLUMNS SIZE 254′);

    Table dropped.

    Elapsed: 00:00:00.12
    SQL>
    Table dropped.

    Elapsed: 00:00:00.14
    SQL>
    Table dropped.

    Elapsed: 00:00:00.12
    SQL> SQL>
    Table created.

    Elapsed: 00:00:01.00
    SQL>
    Table created.

    Elapsed: 00:00:00.93
    SQL>
    Table created.

    Elapsed: 00:00:01.32
    SQL> SQL>
    Index created.

    Elapsed: 00:00:00.56
    SQL>
    Index created.

    Elapsed: 00:00:00.60
    SQL>
    Index created.

    Elapsed: 00:00:00.54
    SQL> SQL>
    PL/SQL procedure successfully completed.

    Elapsed: 00:00:00.45
    SQL>
    PL/SQL procedure successfully completed.

    Elapsed: 00:00:00.46
    SQL>
    PL/SQL procedure successfully completed.

    Elapsed: 00:00:00.46
    SQL>

    SQL> ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=10;

    Session altered.

    SQL>
    SQL> VAR v VARCHAR2(100)

    SQL> SQL> EXEC :v:=’SCOTT’

    SET TIMING ON

    PL/SQL procedure successfully completed.

    SQL> SQL> SQL>
    SQL> PROMPT Running query first time, this should be fast (and should use nested loops execution plan)
    Running query first time, this should be fast (and should use nested loops execution plan)
    SQL>
    SQL> SELECT
    2 MIN(t1.created), MAX(t1.created)
    3 FROM
    4 t1
    5 , t2
    6 , t3
    7 WHERE
    8 t1.object_id = t2.object_id
    9 AND t2.object_id = t3.object_id
    10 AND t1.owner = :v
    11 AND t2.owner = :v
    12 AND t3.owner = :v
    13 /

    SET TIMING OFF

    –SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null,’ALLSTATS LAST ADVANCED’));
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null));

    MIN(T1.CR MAX(T1.CR
    ——— ———

    Elapsed: 00:00:00.01
    SQL> SQL> SQL> SQL> SQL>
    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————
    SQL_ID 5vy5qjd3fsn5c, child number 0
    ————————————-
    SELECT MIN(t1.created), MAX(t1.created) FROM t1 , t2 , t3
    WHERE t1.object_id = t2.object_id AND t2.object_id = t3.object_id
    AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v

    Plan hash value: 4162198323

    —————————————————————————————-
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
    —————————————————————————————-

    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————
    | 0 | SELECT STATEMENT | | | | 3 (100)| |
    | 1 | SORT AGGREGATE | | 1 | 66 | | |
    | 2 | NESTED LOOPS | | | | | |
    | 3 | NESTED LOOPS | | 6 | 396 | 3 (0)| 00:00:01 |
    | 4 | NESTED LOOPS | | 6 | 282 | 2 (0)| 00:00:01 |
    | 5 | TABLE ACCESS BY INDEX ROWID| T1 | 6 | 168 | 1 (0)| 00:00:01 |
    |* 6 | INDEX RANGE SCAN | I1 | 6 | | 1 (0)| 00:00:01 |
    |* 7 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 19 | 1 (0)| 00:00:01 |
    |* 8 | INDEX RANGE SCAN | I2 | 6 | | 1 (0)| 00:00:01 |
    |* 9 | INDEX RANGE SCAN | I3 | 6 | | 1 (0)| 00:00:01 |
    |* 10 | TABLE ACCESS BY INDEX ROWID | T3 | 1 | 19 | 1 (0)| 00:00:01 |

    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————
    —————————————————————————————-

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

    6 – access(“T1″.”OWNER”=:V)
    7 – filter(“T1″.”OBJECT_ID”=”T2″.”OBJECT_ID”)
    8 – access(“T2″.”OWNER”=:V)
    9 – access(“T3″.”OWNER”=:V)
    10 – filter(“T2″.”OBJECT_ID”=”T3″.”OBJECT_ID”)

    33 rows selected.

    SQL> EXEC :v:=’SYS’

    PL/SQL procedure successfully completed.

    Elapsed: 00:00:00.00
    SQL> SQL> SET TIMING ON
    SQL>
    SQL> PROMPT Now running the same query with different bind variables (this query should take very long time)
    Now running the same query with different bind variables (this query should take very long time)
    SQL>
    SQL> SELECT
    2 MIN(t1.created), MAX(t1.created)
    3 FROM
    4 t1
    5 , t2
    6 , t3
    7 WHERE
    8 t1.object_id = t2.object_id
    9 AND t2.object_id = t3.object_id
    10 AND t1.owner = :v
    11 AND t2.owner = :v
    12 AND t3.owner = :v
    13 /

    MIN(T1.CR MAX(T1.CR
    ——— ———
    16-SEP-05 23-FEB-10

    Elapsed: 00:00:00.08
    SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(null,null));

    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————
    SQL_ID 5vy5qjd3fsn5c, child number 2
    ————————————-
    SELECT MIN(t1.created), MAX(t1.created) FROM t1 , t2 , t3
    WHERE t1.object_id = t2.object_id AND t2.object_id = t3.object_id
    AND t1.owner = :v AND t2.owner = :v AND t3.owner = :v

    Plan hash value: 710168226

    —————————————————————————–
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
    —————————————————————————–

    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————
    | 0 | SELECT STATEMENT | | | | 635 (100)| |
    | 1 | SORT AGGREGATE | | 1 | 66 | | |
    |* 2 | HASH JOIN | | 29374 | 1893K| 635 (1)| 00:00:08 |
    |* 3 | TABLE ACCESS FULL | T3 | 30485 | 565K| 211 (1)| 00:00:03 |
    |* 4 | HASH JOIN | | 29374 | 1348K| 423 (1)| 00:00:06 |
    |* 5 | TABLE ACCESS FULL| T2 | 29375 | 545K| 211 (1)| 00:00:03 |
    |* 6 | TABLE ACCESS FULL| T1 | 30301 | 828K| 211 (1)| 00:00:03 |
    —————————————————————————–

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

    PLAN_TABLE_OUTPUT
    ————————————————————————————————————————————————————————————

    2 – access(“T2″.”OBJECT_ID”=”T3″.”OBJECT_ID”)
    3 – filter(“T3″.”OWNER”=:V)
    4 – access(“T1″.”OBJECT_ID”=”T2″.”OBJECT_ID”)
    5 – filter(“T2″.”OWNER”=:V)
    6 – filter(“T1″.”OWNER”=:V)

    29 rows selected.

    Elapsed: 00:00:00.03
    SQL>

  7. Vinicius Hoffmann Bernardes says:

    Hey Tanel!

    I have a similar problem on a production environment at Brazil.
    Do you think you can help me?

    My problem is a query that changes it’s behavior (execution plan) from time to time. When the time comes what happens is that we see a lot of “latch: cache buffer chains” and a huge CPU Spike because of the plan choosen.

    All the colums of the tables involved have histograms and the table stat are not updated very often, also the sample used to collect stat from the tables are about 5%, what i think that can be too low.

    I recommended to collect stat more often and with a bigger sample, but we have the problem even 2 days after the stat gathering.

    What can i do next? Can you reply by e-mail?

    Thank you very much.

  8. Tanel Poder says:

    @Boris Vayntrub
    No Boris,

    When you removed the parameter then you just got “lucky” enough to get a suitable plan which worked fine for both cases. The adaptive bind peeking didn’t even have to kick in. I just used this parameter for generating one of the “unlucky” cases reliably. Without this parameter, yes everything works in your databas X & Y, but give it a few months and something *will* go wrong in database Z some day and generate such a plan…

    My demo was however, entirely about the fact that IF – I repeat IF – you do get such a plan with nested loops (like I showed, for whatever reason – there are gazillions of reasons) during the first execution, then the adaptive bind peeking ain’t gonna help you during 2nd exec. On third it will.

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>