Issue with Autotrace ! Criticality of Using a Right tool…..
November 7, 2013 2 Comments
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.