Autotrace Lies Too!

I posted earlier on Explain Plan’s tendency to spread rumors (Explain Plan Lies). Autotrace is another commonly used tool that suffers from the same basic character flaw (i.e. it lies too). The reason is simple. It uses the Explain Plan command under the covers.

Here’s a quick demonstration:

> 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.

So I flushed the shared pool, executed my statement, and autotrace says it did a full table scan on my Skew table. But it completed in less than a second – so I doubt that’s true. Note also that autotrace says I only did 250 lio’s (the table actually has over 150K blocks).

Next we looked in v$sql for any statements that contained the string “test autotrace”. We found 3 statements:

  1. the current statement doing the lookup in v$sql (68zbpw01f4gh5)
  2. the actual statement that we were looking for (2h0ajqmn8zgww)
  3. and an Explain Plan statement (9hv3fa42xhcm1)

Finally, we looked at the plan that statement 2h0ajqmn8zgww had actually used with dbms_xplan.display_cursor. It shows that the statement actually did an Index Range Scan, not a Full Table Scan.

By the way, this example is on 11gR2, but it behaves the same way in 10g.

So there you have it. Autotrace lies too! (at least it can, on the plan part of the output, due to it’s reliance on the Explain Plan command)

Update: I just ran across this post by Tom Kyte that precedes mine by about 3 years. Better later than never I guess.

3 Comments

  1. One of the more difficult challenges is making TKPROF lie without using the EXPLAIN keyword on the command line – see the example here:
    http://hoopercharles.wordpress.com/2010/01/11/explain-plan-lies-autotrace-lies-tkprof-lies-what-is-the-plan/

  2. osborne says:

    Interesting. I must admit that I don’t use tkprof very often and I have not run into the situation where it gives bad plan information before. I’ll have to play around with it a bit.

    Kerry

  3. [...] Osborne asserts that autotrace lies too, following up an older post of his on explain plan’s untruths: “Autotrace is another [...]

Leave a Reply