GotoDBA Database Tuning,Troubleshooting The Problem with autotrace

The Problem with autotrace

July 6, 2016July 6, 2016 | Liron AmitziLiron Amitzi | 3 Comments | 9:42 am
Categories:

There are few ways to see the execution plan of a SQL statement. One of these ways is the autotrace option in sqlplus. It is a very easy-to-use feature and people use it quite often. But there is a risk here. The autotrace option doesn’t always show you the correct execution plan.
Lately I prepared a demo and had a simple case that showed the incorrect info from autotrace, so here it is.

What I’m going to show is a simple table with skewed data (the table has 10K rows, the STATUS column has zero in all rows except five that have the value 1). Note that this test was done on 12.1.0.2 database.
Let’s start by creating and populating the table:

SQL> create table tab1(id number, name varchar2(20), status number(1));
Table created.
SQL> begin
2      for i in 1..10000
3      loop
4        insert into tab1 values(i,'name_'||i,0);
5      end loop;
6      commit;
7    end;
8  /
PL/SQL procedure successfully completed.
SQL> update tab1 set status=1 where mod(id,2000)=0;
5 rows updated.
SQL> commit;
Commit complete.
SQL> create index tab1_status on tab1(status);
Index created.
SQL> exec dbms_stats.gather_table_stats(user,'tab1');
PL/SQL procedure successfully completed.

As you see, I also created an index on the STATUS column and gathered stats.
Now, we will execute a simple query with STATUS=1.

SQL> set autotrace traceonly
SQL> set lines 100
SQL>
SQL> select * from tab1 where status=1;
Execution Plan
----------------------------------------------------------
Plan hash value: 2211052296
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |  5000 | 80000 |     7  (15)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| TAB1 |  5000 | 80000 |     7  (15)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("STATUS"=1)
Statistics
----------------------------------------------------------
1  recursive calls
0  db block gets
39  consistent gets
0  physical reads
0  redo size
805  bytes sent via SQL*Net to client
551  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
5  rows processed
SQL> exec dbms_stats.gather_table_stats(user,'tab1');
PL/SQL procedure successfully completed.
SQL> select * from tab1 where status=1;
Execution Plan
----------------------------------------------------------
Plan hash value: 2717102297
---------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |             |     5 |    80 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| TAB1        |     5 |    80 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | TAB1_STATUS |     5 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("STATUS"=1)
Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
39  consistent gets
0  physical reads
0  redo size
805  bytes sent via SQL*Net to client
551  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
5  rows processed

Note that in the first execution, the optimizer thinks the number of rows with STATUS=1 is 5000. That’s because we don’t have histograms and the optimizer has limited information (it knows the column has 10K rows and 2 distinct values, so it thinks one value will be half of the table). After that I gathered statistics again. As I mentioned, this is Oracle 12c, so it records the predicates I use and gather more comprehensive statistics when needed. In this case, it decided to gather histograms on the STATUS column, so in the 2nd query, the estimation is correct, only 5 rows have STATUS=1. We can also see that the plan has changed to use the index. But there is one strange thing in this output, can you spot it?
Note the consistent gets, it is 39 in both queries. If the second one uses an index, I would guess it would access less blocks that a full table scan, right? Let’s use hints to check that:

SQL> select /*+ full(tab1) */ * from tab1 where status=1;
Execution Plan
----------------------------------------------------------
Plan hash value: 2211052296
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     5 |    80 |     7  (15)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| TAB1 |     5 |    80 |     7  (15)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("STATUS"=1)
Statistics
----------------------------------------------------------
1  recursive calls
0  db block gets
39  consistent gets
0  physical reads
0  redo size
805  bytes sent via SQL*Net to client
551  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
5  rows processed
SQL> select /*+ index(tab1) */ * from tab1 where status=1;
Execution Plan
----------------------------------------------------------
Plan hash value: 2717102297
---------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |             |     5 |    80 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| TAB1        |     5 |    80 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | TAB1_STATUS |     5 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("STATUS"=1)
Statistics
----------------------------------------------------------
1  recursive calls
0  db block gets
8  consistent gets
0  physical reads
0  redo size
822  bytes sent via SQL*Net to client
551  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
5  rows processed

As you can see, when I hinted the query to use the index, the consistent gets got down to 8. Let’s use dbms_xplan instead of autotrace:

SQL> set autotrace off
SQL>
SQL> select /*+ full(tab1) */ * from tab1 where status=1;
        ID NAME                 STATUS
---------- -------------------- ----------
      4000 name_4000                     1
      2000 name_2000                     1
      6000 name_6000                     1
      8000 name_8000                     1
     10000 name_10000                    1
SQL> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  2xm1q9cbhut9w, child number 0
-------------------------------------
select /*+ full(tab1) */ * from tab1 where status=1
Plan hash value: 2211052296
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     7 (100)|          |
|*  1 |  TABLE ACCESS FULL| TAB1 |     5 |    80 |     7  (15)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("STATUS"=1)
18 rows selected.
SQL> select /*+ index(tab1) */ * from tab1 where status=1;
        ID NAME                     STATUS
---------- -------------------- ----------
      4000 name_4000                     1
      2000 name_2000                     1
      6000 name_6000                     1
      8000 name_8000                     1
     10000 name_10000                    1
SQL> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  05c3acq1b6jsd, child number 0
-------------------------------------
select /*+ index(tab1) */ * from tab1 where status=1
Plan hash value: 2717102297
---------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |             |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| TAB1        |     5 |    80 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | TAB1_STATUS |     5 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("STATUS"=1)
19 rows selected.
SQL> select * from tab1 where status=1;
        ID NAME                     STATUS
---------- -------------------- ----------
      4000 name_4000                     1
      2000 name_2000                     1
      6000 name_6000                     1
      8000 name_8000                     1
     10000 name_10000                    1
SQL> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  bazxtqtrkhu6p, child number 0
-------------------------------------
select * from tab1 where status=1
Plan hash value: 2211052296
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     7 (100)|          |
|*  1 |  TABLE ACCESS FULL| TAB1 |  5000 | 80000 |     7  (15)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("STATUS"=1)
18 rows selected.

With the hints, we got the expected plan, but without it, we got a full table scan and an estimation of 5000 rows. This is because this cursor already exists in the shared pool so it is reused. Now, we will try the same query with upper case “select”, to create a new cursor:

SQL> SELECT * from tab1 where status=1;
        ID NAME                     STATUS
---------- -------------------- ----------
      4000 name_4000                     1
      2000 name_2000                     1
      6000 name_6000                     1
      8000 name_8000                     1
     10000 name_10000                    1
SQL> select * from table(dbms_xplan.display_cursor);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  b1rchytsxzx96, child number 0
-------------------------------------
SELECT * from tab1 where status=1
Plan hash value: 2717102297
---------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |             |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| TAB1        |     5 |    80 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | TAB1_STATUS |     5 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("STATUS"=1)
19 rows selected.

Now it looks OK, how about autotrace?

SQL> set autotrace traceonly
SQL> SELECT * from tab1 where status=1;
Execution Plan
----------------------------------------------------------
Plan hash value: 2717102297
---------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |             |     5 |    80 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| TAB1        |     5 |    80 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | TAB1_STATUS |     5 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("STATUS"=1)
Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
8  consistent gets
0  physical reads
0  redo size
822  bytes sent via SQL*Net to client
551  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
5  rows processed

Now both the plan and statistics are as expected.
So as you can see, the “autotrace” option in sqlplus calculates a new plan for your query, and doesn’t show the real plan from Oracle’s shared pool. That’s why it can’t be trusted. When checking plans during a SQL tuning session, you should use DBMS_XPLAN.

3 thoughts on “The Problem with autotrace”

  1. Hi Liron,
    Thanks for this nice post!
    You mentioned that autotrace can’t be trusted and it is better to use DBMS_XPLAN. I find this a bit strange because AFAIK they both do the same since autotrace is just a SQL*PLUS feature which uses DBMS_XPLAN behind the scenes.

    Reply

  2. I assume that you meant to say that we should use “dbms_xplan.display_cursor” for a tuning session since both autotrace and ‘explain plan for (QUERY)’; then ‘select * from table(dbms_xplan.display);’ do the same and use the ESTIMATED plan instead of the ACTUAL PLAN.
    BTW, another option is to use V$SQL_PLAN and V$SQL_PLAN_STATISTICS. They both provide the ACTUAL plan information

    Reply

  3. Pini,
    Thanks for the comment, I traced the “set autotrace” to verify that before I’m answering. Autotrace is using the “explain plan for” command which parses the query and inserts the results into the PLAN_TABLE. After that it uses DBMS_XPLAN.DISPLAY only to format the content of the PLAN_TABLE and display the results. DBMS_XPLAN.DISPLAY_CURSOR doesn’t parse any query, it takes the SQL_ID and queries the V$ views you mentioned to get the actual plan Oracle used for the query.
    Another thing, “explain plan for” (so autotrace as well) sometimes has specific behavior. For example, as far as I remember it doesn’t perform bind peeking (that’s why you can run “explain plan for” for a query with bind variable without declaring the variable).
    So what I meant in this post, is running DBMS_XPLAN to get the plan from memory vs. running autotrace that parses the query and generates a new plan.
    Liron

    Reply

Leave a Reply

Your email address will not be published. Required fields are marked *

Related Post