Oracle's Autotrace Can Lie to You

Monday Aug 14th 2017 by David Fitzjarrell
Share:

Execution plans can be very helpful when diagnosing problems but be careful how you generate them as autotrace can lie to you.  Read on to see how to generate reliable execution plans.

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
 
SYS@LAB112> @flush_pool
 
System altered.
 
SYS@LAB112> @avgskew_X
SYS@LAB112> var X varchar2(2);
SYS@LAB112> exec :X := 'N';
 
PL/SQL procedure successfully completed.
 
SYS@LAB112> -- should cause index access due to histogram on col4
SYS@LAB112>
SYS@LAB112> set autotrace on
SYS@LAB112> 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
 
SYS@LAB112>
SYS@LAB112> set autotrace off
SYS@LAB112>
SYS@LAB112> 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.
 
SYS@LAB112>
SYS@LAB112> 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

Share:
Home
Mobile Site | Full Site
Copyright 2017 © QuinStreet Inc. All Rights Reserved