Issue with Autotrace ! Criticality of Using a Right tool…..

As mentioned in my previous blog, my visit to Oracle Open World was very exciting and enriching. Every session I attended, I got to know something new and therefore thought of sharing this with my readers. I actually wanted to demonstrate this during my Sangam 2013 presentation. However, due to some official commitments, I had to pull out from the event.

In many of my presentations, especially for Developers, I had covered some concepts (along with the Demonstration) on Bind Peeking and issues with “Explain Plan” or Autotrace, as these are not bind-aware. This means, if a query contains a bind variable and if the execution plan of that query is dependant on the value provided to the bind, then the execution plan displayed (or generated) by “explain plan” / “autotrace” is not guaranted to be the same as that of runtime optimizer. Even today, I see many developers (and DBA’s as well) use either “explain plan for” or “autotrace” utilities to check for the execution plan of the queries they are working on.

I attended a very good session that was jointly presented by Maria Colgan and Jonathan Lewis. Maria mentioned about an issue with “set autot trace explain”, which has a potential of creating a (sub-optimal) plan and can cause a performance bottleneck as this sub-optimal plan can then be shared by other users.

Randolf Geist has already published a very good note on this issue and should help my readers understand this as it has been explained with good examples. However, since I was working on the demonstration to be presented during Sangam 2013, thought of sharing this here.

The demonstration is as under :


## Table Creation

drop table t1;

create table t1 as
select a.* from all_objects a, all_objects b
where rownum<=1e6;
create index t1_idx on t1(temporary);

select temporary, count(*) from t1 group by temporary;

exec dbms_stats.gather_table_stats(user,'T1',method_opt=>'for all columns size 1, for columns temporary size 100');

We created a table t1 with 1 Million Rows and an Index on Temporary Column. This Index has been created to demonstrate the difference in the plan when we query data on Temporary Column. Further, in order for the optimizer to generate different plan, we gather histogram on this column. This additional statistics will ensure that optimizer generates / computes the cardinality and the plan based on the input value.

Next, we execute two queries, one each with a Literal Value of ‘Y’ and a Bind Variable with Y passed as a value to the Bind. In both the case, the Optimizer computes nearly accurate cardinality and Index Scan Access Path. For the execution with Bind, the optimizer peeked into Bind to come out with the cardinality and Index Access Path.

select /*+ vivek_y */ OWNER, OBJECT_NAME from t1 where temporary='Y';

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------
SQL_ID  7zfa7mstt63gv, child number 0
-------------------------------------
select /*+ vivek_y */ OWNER, OBJECT_NAME from t1 where temporary='Y'

Plan hash value: 546753835

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |    47 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1     |  2680 | 88440 |    47   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T1_IDX |  2680 |       |     7   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

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

   2 - access("TEMPORARY"='Y')

variable b1 varchar2(32);
exec :b1:='Y';

select /*+ vivek_bind_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1;

SQL_ID  9c5pp1gt64s7q, child number 0
-------------------------------------
select /*+ vivek_bind_y */ OWNER, OBJECT_NAME from t1 where
temporary=:b1

Plan hash value: 546753835

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |    47 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1     |  2680 | 88440 |    47   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T1_IDX |  2680 |       |     7   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - :B1 (VARCHAR2(30), CSID=178): 'Y'

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

   2 - access("TEMPORARY"=:B1)


Let us check for the behaviour of “explain plan for” and “autotrace” utilities. Since these are not bind-aware, the plan displayed & generated will be a Full Table Scan. The computed cardinality is based on #Rows/NDV, which is 1000000/2 = 500000. Also, note the I/O’s (consistent read) as generated by autotrace.

explain plan for
select /*+ vivek_bind_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1;

SQL> @utlxpls

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   500K|    15M|  3968   (2)| 00:00:48 |
|*  1 |  TABLE ACCESS FULL| T1   |   500K|    15M|  3968   (2)| 00:00:48 |
--------------------------------------------------------------------------

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

   1 - filter("TEMPORARY"=:B1)

set autot trace
select /*+ vivek_bind_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1;

2327 rows selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   500K|    15M|  3968   (2)| 00:00:48 |
|*  1 |  TABLE ACCESS FULL| T1   |   500K|    15M|  3968   (2)| 00:00:48 |
--------------------------------------------------------------------------

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

   1 - filter("TEMPORARY"=:B1)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        841  consistent gets <--- Note the I/O
          0  physical reads
          0  redo size

set autot trace

Last, we execute the query with “set autot trace explain” and the same query with “set autot off”. In this case, while the value passed to the bind is ‘Y’, the optimizer will re-use the plan (Full Table Scan) generated by “set autot trace explain” and this is where the problem starts. With “set autot trace explain”, the plan generated is stored in the Shared Pool and is shared by the same query, if run from an application and this can be a problem. Assuming the query executed next is a part of the application query and a developer runs the exactly same query using “set autot trace explain”, the plan generated will be without bind peek and will be sub-optimal.

set autot trace explain
select /*+ with_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1;


SQL> @ap

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  cbf51h7v1276h, child number 0
-------------------------------------
select /*+ with_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |  3968 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |   500K|    15M|  3968   (2)| 00:00:48 |
--------------------------------------------------------------------------

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

   1 - filter("TEMPORARY"=:B1)


18 rows selected.

set autot off
select /*+ with_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1;

select plan_table_output from table(dbms_xplan.display_cursor(format=>'typical +peeked_binds'));

SQL_ID  cbf51h7v1276h, child number 0
-------------------------------------
select /*+ with_y */ OWNER, OBJECT_NAME from t1 where temporary=:b1

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |  3967 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |   500K|    15M|  3967   (2)| 00:00:48 |
--------------------------------------------------------------------------

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

   1 - filter("TEMPORARY"=:B1)

new   1: select sql_id, sql_text, executions, buffer_gets, elapsed_time, rows_processed from v$sqlarea where sql_id='cbf51h7v1276h'

SQL_ID        SQL_TEXT                                           EXECUTIONS BUFFER_GETS ELAPSED_TIME ROWS_PROCESSED
------------- -------------------------------------------------- ---------- ----------- ------------ --------------
cbf51h7v1276h select /*+ with_y */ OWNER, OBJECT_NAME from t1 wh          1       14393      3563761           2327
              ere temporary=:b1

The last query is exactly same to the one that was executed with “set autot trace explain” and shared the plan generated by “set autotrace explain”, which is a Full table scan and is not the one that should have been generated. Interestingly, check for the I/O’s of the last Full Table Scan plan query. The query has done 14393 Logical reads, whereas, in one of the previous execution with “autotrace on”, the I/O’s shown was 891 (and the plan says full table scan). Why is there a difference between the two I/O’s of Full Table Scans ? For an explanation, read the blog from Randolf Geist.

About these ads

About Vivek Sharma
I am an Oracle Professional from Mumbai (India). I blog on the issues that I feel is Interesting for my readers. These are all my real life examples, which I hope, you would find interesting. Comments are always a welcome.

2 Responses to Issue with Autotrace ! Criticality of Using a Right tool…..

  1. Onkar says:

    Good post Vivek but I think something is missing here:

    create table t1 as
    select a.* from all_objects a, all_objects b
    where rownum’for all columns size 1, for columns temporary size 100′); — this line?

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 125 other followers