Oracle’s Autotrace Can Lie to You

Query tuning is part art, part science and it depends upon reliable information from Oracle, most often in the form of query execution plans. There are several ways to generate such plans, three of which are ‘autotrace traceonly explain’, ‘explain plan’ and the dbms_xplan package. The first two options won’t return any data, which makes them convenient options to view a plan without having to wait for a huge result set to display, but there could be ‘trouble in paradise’ when using them. In older releases ‘explain plan’ and ‘autotrace traceonly explain’ could return a plan that didn’t agree with reality, and there may be circumstances with current releases that generate that same behavior. Let’s look at an example from Kerry Osborne to illustrate this.

In recent releases of Oracle, the various methods listed above usually provide the same execution plan for the same query:


PLAGNEZIUS @ flurgenhoot > set autotrace traceonly
PLAGNEZIUS @ flurgenhoot > 
PLAGNEZIUS @ flurgenhoot > select avg(c_1) from test1 where c_2 = :x;


Execution Plan
----------------------------------------------------------                                                                                            
Plan hash value: 3185605318                                                                                                                           
                                                                                                                                                      
-----------------------------------------------------------------------------                                                                         
| Id  | Operation         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |                                                                         
-----------------------------------------------------------------------------                                                                         
|   0 | SELECT STATEMENT  |         |     1 |     5 |     1   (0)| 00:00:01 |                                                                         
|   1 |  SORT AGGREGATE   |         |     1 |     5 |            |          |                                                                         
|*  2 |   INDEX RANGE SCAN| TEST1_C |    55 |   275 |     1   (0)| 00:00:01 |                                                                         
-----------------------------------------------------------------------------                                                                         
                                                                                                                                                      
Predicate Information (identified by operation id):                                                                                                   
---------------------------------------------------                                                                                                   
                                                                                                                                                      
   2 - access("C_2"=:X)                                                                                                                               

...

PLAGNEZIUS @ flurgenhoot > explain plan
  2  set statement_id = 'test3'
  3  for
  4  select avg(c_1) from test1 where c_2 = :x;

Explained.

PLAGNEZIUS @ flurgenhoot > 
PLAGNEZIUS @ flurgenhoot > SELECT cardinality "Rows",
  2  	    lpad(' ',level-1)||operation||' '||
  3  	    options||' '||object_name "Plan"
  4    FROM PLAN_TABLE
  5  CONNECT BY prior id = parent_id
  6  	     AND prior statement_id = statement_id
  7    START WITH id = 0
  8  	     AND statement_id = 'test3'
  9    ORDER BY id;

      Rows Plan                                                                                                                                       
---------- --------------------------------------------------------------------------------                                                           
         1 SELECT STATEMENT                                                                                                                           
         1  SORT AGGREGATE                                                                                                                            
        55   INDEX RANGE SCAN TEST1_C                                                                                                                 

...

PLAGNEZIUS @ flurgenhoot > select avg(c_1) from test1 where c_2 = :x;

  AVG(C_1)                                                                                                                                            
----------                                                                                                                                            
5.80733945                                                                                                                                            

PLAGNEZIUS @ flurgenhoot > 
PLAGNEZIUS @ flurgenhoot > select * From table(dbms_xplan.display_Cursor());

PLAN_TABLE_OUTPUT                                                                                                                                     
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  78j9xu1k90fky, child number 0                                                                                                                 
-------------------------------------                                                                                                                 
select avg(c_1) from test1 where c_2 = :x                                                                                                             
                                                                                                                                                      
Plan hash value: 3185605318                                                                                                                           
                                                                                                                                                      
-----------------------------------------------------------------------------                                                                         
| Id  | Operation         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |                                                                         
-----------------------------------------------------------------------------                                                                         
|   0 | SELECT STATEMENT  |         |       |       |     1 (100)|          |                                                                         
|   1 |  SORT AGGREGATE   |         |     1 |     5 |            |          |                                                                         
|*  2 |   INDEX RANGE SCAN| TEST1_C |   109 |   545 |     1   (0)| 00:00:01 |                                                                         
-----------------------------------------------------------------------------                                                                         
                                                                                                                                                      
Predicate Information (identified by operation id):                                                                                                   
---------------------------------------------------                                                                                                   
                                                                                                                                                      
   2 - access("C_2"=:X)                                                                                                                               
                                                                                                                                                      

19 rows selected.

There could be times, however, where the plans generated by autotrace don’t match with those generated by dbms_xplan; this example from Kerry Osborne, using Oracle 11.2.0.1, illustrates this:


> sqlplus "/ as sysdba"
 
SQL*Plus: Release 11.2.0.1.0 Production on Mon Feb 15 11:51:27 2010
 
Copyright (c) 1982, 2009, Oracle.  All rights reserved.
 
 
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
 
[email protected]> @flush_pool
 
System altered.
 
[email protected]> @avgskew_X
[email protected]> var X varchar2(2);
[email protected]> exec :X := 'N';
 
PL/SQL procedure successfully completed.
 
[email protected]> -- should cause index access due to histogram on col4
[email protected]>
[email protected]> set autotrace on
[email protected]> select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X
  2  /
 
 AVG(PK_COL)
------------
961866206.84
 
1 row selected.
 
 
Execution Plan
----------------------------------------------------------
Plan hash value: 568322376
 
---------------------------------------------------------------------------
| Id  | Operation		  | Name | Rows  | Bytes | Cost (%CPU)| Time	 
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |	  |	 1 |	24 | 28420   (2)| 00:05:42 
|   1 |  SORT AGGREGATE	|	  |	 1 |	24 |			|		  
|*  2 |   TABLE ACCESS FULL| SKEW |	10M|   244M| 28420   (2)| 00:05:42 
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - filter("COL4"=:X)
 
 
Statistics
----------------------------------------------------------
		737  recursive calls
		  0  db block gets
		250  consistent gets
		  0  physical reads
		  0  redo size
		444  bytes sent via SQL*Net to client
		420  bytes received via SQL*Net from client
		  2  SQL*Net roundtrips to/from client
		  7  sorts (memory)
		  0  sorts (disk)
		  1  rows processed
 
[email protected]>
[email protected]> set autotrace off
[email protected]>
[email protected]> select sql_id, child_number, sql_text from v$sql where sql_text like '%test autotrace%'
  2  /
 
SQL_ID		CHILD_NUMBER
------------- ------------
SQL_TEXT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
9hv3fa42xhcm1			0
EXPLAIN PLAN SET STATEMENT_ID='PLUS4294967295' FOR select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X
 
68zbpw01f4gh5			0
select sql_id, child_number, sql_text from v$sql where sql_text like '%test autotrace%'
 
2h0ajqmn8zgww			0
select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X
 
 
3 rows selected.
 
[email protected]>
[email protected]> select * from table(dbms_xplan.display_cursor('2h0ajqmn8zgww','','typical'))
  2  /
 
PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  2h0ajqmn8zgww, child number 0
-------------------------------------
select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X
 
Plan hash value: 1946853647
 
------------------------------------------------------------------------------------------
| Id  | Operation					| Name	  | Rows  | Bytes | Cost (%CPU)| Time	 
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT			 |		   |	   |	   |	25 (100)|		  
|   1 |  SORT AGGREGATE			  |		   |	 1 |	24 |			|		  
|   2 |   TABLE ACCESS BY INDEX ROWID| SKEW	  |  3170 | 76080 |	25   (0)| 00:00:01 
|*  3 |	INDEX RANGE SCAN		  | SKEW_COL4 |  3170 |	   |	 8   (0)| 00:00:01 
------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   3 - access("COL4"=:X)
 
 
20 rows selected.

Using autotrace with the ‘traceonly explain’ option shows a full table scan as the access method, yet dbms_xplan.display_cursor() reveals the actual access method, an index range scan (which is the expected plan).

In many forums and newsgroups those posting questions have used explain plan to generate execution plans and, as seen above, Oracle has done a fairly good job of getting the various plan generation methods to agree. But there can be cases where this is not the case; plans generated by ‘autotrace traceonly explain’ or ‘explain plan’ should be verified by using the dbms_xplan package since it accesses the plan information found in the V$SQL_PLAN view. It may be a rare occurrence in current releases where plans from all three methods don’t agree, but it can happen. Oracle recommends the use of the dbms_xplan package to generate plans, and that should be the standard method for generating such plans.

Yes, ‘autotrace traceonly explain’ and ‘explain plan’ can be convenient options to display plans, just realize that they may not always agree with the output from dbms_xplan.

See all articles by David Fitzjarrell

David Fitzjarrell
David Fitzjarrell has more than 20 years of administration experience with various releases of the Oracle DBMS. He has installed the Oracle software on many platforms, including UNIX, Windows and Linux, and monitored and tuned performance in those environments. He is knowledgeable in the traditional tools for performance tuning – the Oracle Wait Interface, Statspack, event 10046 and 10053 traces, tkprof, explain plan and autotrace – and has used these to great advantage at the U.S. Postal Service, American Airlines/SABRE, ConocoPhilips and SiriusXM Radio, among others, to increase throughput and improve the quality of the production system. He has also set up scripts to regularly monitor available space and set thresholds to notify DBAs of impending space shortages before they affect the production environment. These scripts generate data which can also used to trend database growth over time, aiding in capacity planning. He has used RMAN, Streams, RAC and Data Guard in Oracle installations to ensure full recoverability and failover capabilities as well as high availability, and has configured a 'cascading' set of DR databases using the primary DR databases as the source, managing the archivelog transfers manually and montoring, through scripts, the health of these secondary DR databases. He has also used ASM, ASMM and ASSM to improve performance and manage storage and shared memory.

Latest Articles