Autotrace trick

(… as in “trick or treat”)

Here’s an important threat I learned from Maria Colgan’s “10 tips” presentation on Tuesday of Open World. It comes in two steps – the first step is the bit that most people know but the second step reveals the unexpected consequences:

1. The autotrace facility in SQL*PLus can give misleading execution plans for queries that use bind variables because autotrace doesn’t peek
2. if you run a query after testing it with autotrace, the plan generated by autotrace can be shared by the later execution

Here’s a simple script I’ll be using to demonstrate the behaviour:

set autotrace traceonly explain

select id from t1 where skew = 1;
select id from t1 where skew = 80;

variable b1 number
exec :b1 := 1

select id from t1 where skew = :b1;

set autotrace off

select id from t1 where skew = :b1;
select * from table(dbms_xplan.display_cursor(null,null,'peeked_binds'));

The table t1 has one row where skew = 1, two where skew = 2, and so on with 80 rows where skew = 80: a total of 3240 rows. I have a perfect frequency histogram on the column, and an index. The clustering_factor of the index is so large that it is only suitable for queries which will return a small number of rows.

In my test case, the predicted plan for the first query uses an index range scan with an estimated cardinality of 1, the second query shows a full tablescan with an estimated cardinality of 80. The third query shows a full tablescan with an estimated cardinality of 41 (the “average” number of rows per distinct value) because autotrace doesn’t peek the bind variable.

Looking at the fourth query – where we’ve finally turned off autotrace – we might assume that the execution plan would be an index range scan because the supplied bind variable has a value of 1 and we might think that the optimizer is going to optimize the statement – but the call to dbms_xplan.display_cursor() shows us that Oracle re-uses the plan previously generated by autotrace.

If you flush the shared pool and repeat the test but exclude the third query, the final query will use the range scan we expect to see.

Here’s a copy of the output from the initial test – with a little cosmetic editing:

Execution Plan
----------------------------------------------------------
Plan hash value: 4175407225

-----------------------------------------------------------------------
| Id  | Operation                   | Name    | Rows  | Bytes | Cost  |
-----------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |     1 |     7 |     2 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1      |     1 |     7 |     2 |
|*  2 |   INDEX RANGE SCAN          | T1_SKEW |     1 |       |     1 |
-----------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("SKEW"=1)

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

----------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost  |
----------------------------------------------------------
|   0 | SELECT STATEMENT  |      |    80 |   560 |    20 |
|*  1 |  TABLE ACCESS FULL| T1   |    80 |   560 |    20 |
----------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("SKEW"=80)

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

----------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost  |
----------------------------------------------------------
|   0 | SELECT STATEMENT  |      |    41 |   287 |    20 |
|*  1 |  TABLE ACCESS FULL| T1   |    41 |   287 |    20 |
----------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("SKEW"=TO_NUMBER(:B1))

==================================================
autotrace off, with an actual bind value available
We re-use the autotrace cursor, and don't report
a bind value (since we didn't peek to optimize).
==================================================

        ID
----------
      3240

PLAN_TABLE_OUTPUT
-----------------
SQL_ID  4a0ywc60thj4a, child number 0
-------------------------------------
select id from t1 where skew = :b1

Plan hash value: 3617692013

----------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost  |
----------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |    20 |
|*  1 |  TABLE ACCESS FULL| T1   |    41 |   287 |    20 |
----------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("SKEW"=:B1)

If you comment out the third query, flush the shared pool and repeat, the final call to dbms_xplan gives the following output:

PLAN_TABLE_OUTPUT
-----------------
SQL_ID  4a0ywc60thj4a, child number 0
-------------------------------------
select id from t1 where skew = :b1

Plan hash value: 4175407225

-----------------------------------------------------------------------
| Id  | Operation                   | Name    | Rows  | Bytes | Cost  |
-----------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |       |       |     2 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1      |     1 |     7 |     2 |
|*  2 |   INDEX RANGE SCAN          | T1_SKEW |     1 |       |     1 |
-----------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - :B1 (NUMBER): 1

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("SKEW"=:B1)

If you want to repeat the test in your own environment, here’s the code to generate the table and index:

create table t1 (
	id, skew, padding
)
as
select rownum, r1, rpad('x',400)
from
(
	select /*+ no_merge */
		rownum r1
	from all_objects
	where rownum <= 80
)	v1,
(
	select /*+ no_merge */
		rownum r2
	from all_objects
	where rownum <= 80
)	v2
where   r2 <= r1
order by r2,r1
;

alter table t1 modify skew not null;

create index t1_skew on t1(skew);

begin
	dbms_stats.gather_table_stats(
		ownname		 => user,
		tabname		 => 'T1',
		method_opt 	 => 'for all columns size 254'
	);
end;
/

Footnote:

If you’re using the autotrace that comes with (recent versions) of SQL*Developer, the feature asks you to supply values for the bind variables, runs the query then pulls the plan and execution stats from memory, so this note doesn’t apply.