Can we trust AUTOTRACE?
In short the answer is NO. I mean it is likely to be accurate in most of the cases, but there are situations when it dissplays different execution plan, not the one that’s really used to execute the SQL.
Take a look at this sample. First I create a table that contains skew data (few “0”s and lots of “1”s) in column y and then I gather the statistics without histograms on column y. After that’s done a test query is executed counting rows where y=0.
$ sqlplus /
SQL*Plus: Release 11.2.0.1.0 Production on Tue Aug 24 12:20:35 2010
Copyright (c) 1982, 2009, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ops$oramel@mel1> CREATE TABLE test1 AS
2 SELECT
3 CASE
4 WHEN rownum<100 THEN 0
5 ELSE 1 END AS y,
6 lpad('X',100,'X') AS z
7 FROM DUAL
8 CONNECT BY LEVEL <= 1000000;
Table created.
ops$oramel@mel1> CREATE INDEX test1_i ON test1(y);
Index created.
ops$oramel@mel1> EXEC dbms_stats.gather_table_stats('OPS$ORAMEL','TEST1',cascade=>true, estimate_percent=>100);
PL/SQL procedure successfully completed.
ops$oramel@mel1> set autotrace on
ops$oramel@mel1> SELECT /*TEST_CASE_1*/ count(z) FROM test1 WHERE y=0;
COUNT(Z)
----------
99
Execution Plan
----------------------------------------------------------
Plan hash value: 3896847026
----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 104 | 3802 (1)| 00:00:55 |
| 1 | SORT AGGREGATE | | 1 | 104 | | |
|* 2 | TABLE ACCESS FULL| TEST1 | 500K| 49M| 3802 (1)| 00:00:55 |
----------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter('Y'=0)
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
15156 consistent gets
15152 physical reads
0 redo size
526 bytes sent via SQL*Net to client
524 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
As there are only 2 distinct values and no histograms on column y, the optimizer chooses TABLE FULL SCAN. Let’s create histogram on column y and repeat the testcase using exactly the same query:
ops$oramel@mel1> EXEC dbms_stats.gather_table_stats('OPS$ORAMEL','TEST1',cascade=>true, method_opt=>'for columns y size 254', estimate_percent=>100);
PL/SQL procedure successfully completed.
ops$oramel@mel1> SELECT /*TEST_CASE_1*/ count(z) FROM test1 WHERE y=0;
COUNT(Z)
----------
99
Execution Plan
----------------------------------------------------------
Plan hash value: 2412143026
----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 104 | 5 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 104 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| TEST1 | 99 | 10296 | 5 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | TEST1_I | 99 | | 3 (0)| 00:00:01 |
----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access('Y'=0)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
15156 consistent gets
15152 physical reads
0 redo size
526 bytes sent via SQL*Net to client
524 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
As the histogram is present the optimiser has chosen INDEX RANGE SCAN to access rows where y=0. Do you notice anything wrong there? Take a look at “consistent gets”, it’s 15156 in both cases, so despite INDEX RANGE SCAN was reported, TABLE FULL SCAN was used anyway. The thing is that AUTOTRACE is just a wrapper around “EXPLAIN PLAN ..” statement, it’s not reporting the execution plan that was actually used to execute the statement, but it’s issuing “EXPLAIN PLAN” statement to provide the execution plan for the query. The histogram was created without invalidating the cursors, so the 2nd execution of the query was reusing the plan that was present in the shared pool, but “EXPLAIN PLAN” statements never share cursors, therefore AUTOTRACE reported different execution plan for the 2nd execution of the query. Let’s check v$sql to confirm this:
ops$oramel@mel1> SELECT executions exec, sql_id, child_number chn, sql_text FROM v$sql where sql_text like '%TEST_CASE_1%';
EXEC SQL_ID CHN SQL_TEXT
----- ------------- ---- ----------------------------------------------------------
1 1m1hh2t0swwsa 0 EXPLAIN PLAN SET STATEMENT_ID='PLUS130016' FOR SELECT /*TE
ST_CASE_1*/ count(z) FROM test1 WHERE y=0
1 1m1hh2t0swwsa 1 EXPLAIN PLAN SET STATEMENT_ID='PLUS130016' FOR SELECT /*TE
ST_CASE_1*/ count(z) FROM test1 WHERE y=0
2 3sf3366tfy3yh 0 SELECT /*TEST_CASE_1*/ count(z) FROM test1 WHERE y=0
1 6dmnqmh0jgx27 0 SELECT executions exec, sql_id, child_number chn, sql_text
FROM v$sql where sql_text like '%TEST_CASE_1%'
The test SQL was executed 2 times and there are also 2 EXPLAIN PLAN statements each executed once (by the AUTOTRACE).
If statistics are collected with enabled cursor invalidation, we get a correct picture (consistent gets = 5 now):
ops$oramel@mel1> EXEC dbms_stats.gather_table_stats('OPS$ORAMEL','TEST1',cascade=>true, method_opt=>'for columns y size 254', estimate_percent=>100, no_invalidate=>false);
PL/SQL procedure successfully completed.
ops$oramel@mel1> SELECT /*TEST_CASE_1*/ count(z) FROM test1 WHERE y=0;
COUNT(Z)
----------
99
Execution Plan
----------------------------------------------------------
Plan hash value: 2412143026
----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 104 | 5 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 104 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| TEST1 | 99 | 10296 | 5 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | TEST1_I | 99 | | 3 (0)| 00:00:01 |
----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access('Y'=0)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
5 consistent gets
0 physical reads
0 redo size
526 bytes sent via SQL*Net to client
524 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
So keep in mind AUTOTRACE might be showing different execution plan from what was actually used if the cursor sharing kicks in, either make sure your SQL is unique or extract the execution plan using dbms_xplain.display_cursor or from the trace file.