Explain Plan For command may show you the wrong execution plan – Part 1

In Oracle-L mailing list a question was asked about under which conditions can the explain plan report a wrong execution plan (not the one which was actually used when a problem happened).

I replied this, but thought to show an example test case of this problem too:

1) The optimizer statistics the EXPLAIN PLAN ends up using are different
from the statistics the other session ended up using

2) Explain plan does not use bind variable peeking thus will not optimize
for current bind variable values

3) Explain plan treats all bind variables as VARCHAR2, thus you ma have
implicit datatype conversion happening during the plan execution, (meaning
to_char,to_number functions are added around variables/columns) and this for
example may make optimizer to ignore some indexes if you get unlucky.

…Of course explain plan doesn’t really
execute the plan so the implicit datatype conversion you see is in the
explained plan only, but if you actually execute the statement (with correct
bind datatypes) then there’s no implicit datatype conversion. And that’s
where the difference comes from…

And here comes an example of condition number 3 above. Lets use a little bit of bad design out there and put numeric values into varchar2 columns:

SQL> create table t (id varchar2(10), name varchar2(100));

Table created.

SQL> insert into t select to_char(object_id), object_name from dba_objects;

51449 rows created.

Now we add a little index for lookup performance and gather stats:

SQL> create index i on t(id);

Index created.

SQL> exec dbms_stats.gather_table_stats(user,'T',cascade=>true);

PL/SQL procedure successfully completed.

Now lets define a bind variable of NUMBER type and set a value for it:

SQL> var x number
SQL>
SQL> exec :x:=99999

PL/SQL procedure successfully completed.

Now lets use “explain plan for” to estimate the execution plan:

SQL> explain plan for
 2  select sum(length(name)) from t where id >  :x;

Explained.

SQL> select * from table(dbms_xplan.display) ;

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------
Plan hash value: 3694077449

-------------------------------------------------------------------------------------
| Id  | Operation                    | Name | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |      |     1 |    29 |    56   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE              |      |     1 |    29 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T    |  2572 | 74588 |    56   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | I    |   463 |       |     3   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

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

 3 - access("ID">:X)

15 rows selected.

Explain plan command nicely reports that we’d be using an index range scan, which would be a good thing to do given my test data and search condition.

Now lets actually run the statement and see the REAL execution plan actually used for the execution. I’ll use dbms_xplan.display_CURSOR for this. If you don’t pass SQL_ID/child into that function it will just report the last SQL statement executed in your current session. But the key difference between the dbms_xplan.DISPLAY and DISPLAY_CURSOR is that the latter goes to library cache and fetches the actual SQL plan used from there. The explain plan command just reparses the statement and estimates a plan, ignoring any bind variable values and assuming that all bind variables are of type varchar2:

SQL> select sum(length(name)) from t where id >  :x;

SUM(LENGTH(NAME))
-----------------

SQL> select * from table(dbms_xplan.display_cursor);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------
SQL_ID  7zm570j6kj597, child number 0
-------------------------------------
select sum(length(name)) from t where id >  :x

Plan hash value: 2966233522

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |    60 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    29 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |  2572 | 74588 |    60   (5)| 00:00:01 |
---------------------------------------------------------------------------

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

 2 - filter(TO_NUMBER("ID")>:X)

19 rows selected.

Whatta? We actually used a full table scan!

Also check out a related article by Kerry Osborne

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

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

7 Responses to Explain Plan For command may show you the wrong execution plan – Part 1

  1. Tanel,

    Believe it or not, on 1st November I had sent you a mail describing exact situation. A query on development database was running in few seconds, where as on the production database it was taking around 4 minutes to complete. Number of records were almost the same and the execution plan was showing the INDEX RANGE SCAN on both databases. I was really puzzled about this strange behavior. When I enable 10046 trace, I found that on the production database, it was doing a FTS, though the execution plan via dbms_xplan.display was showing the INDEX RANGE SCAN. However, when I use dbms_xplan.display_cursor to produce the execution plan, surprisingly it gave me FTS. The only change I found between these databases was the CURSOR_SHARING parameter. The development db was having EXACT value and the production db was having SIMILAR value. I had every little time to investigate further due to the tremendous pressure from the business guys, I changed the value on the production SIMILAR to EXACT and the query ran in few seconds as it was running on the development. I knew it could be definitely something to do with bind variable peeking.

    If you want, I can resend you all the details if you could think it would help you to investigate further on this behavior.

    Regards,

    Jaffar

  2. Tanel Poder says:

    Hi Jaffar,

    That’s probably a classic issue of bind variable peeking where “wrong” bind variable values were used for initial hard parse of the statement. After you changed the parameter, a new cursor was hard parsed due this parameter change and now you got lucky and “right” bind variable values were seen when optimizing the cursor.

  3. Pingback: Blogroll Report 13/11/2009-20/11/2009 « Coskan’s Approach to Oracle

  4. @Tanel Poder
    Hi Tanel,

    If it is the case of bind peeking, then it won’t be a good idea to change the CURSOR_SHARING parameter to EXACT as it may affect other queries as well ? So one should try to avoid using bind variables for that particular query (after being sure that it was actually due to bind peeking only) ? Do I make some sense ? ;)

    Cheers !

  5. madhuri says:

    Tanel,

    Could you please give me some bind peek examples.

    Madhuri

  6. Pingback: What the heck is the INTERNAL_FUNCTION in execution plan predicate section? | Tanel Poder's blog: IT & Mobile for Geeks and Pros

  7. Pingback: Confluence: Productie

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>