Home > DBA, Oracle, SQL > Day 7: The Twelve Days of SQL: EXPLAIN PLAN lies

Day 7: The Twelve Days of SQL: EXPLAIN PLAN lies


On the seventh day of Christmas, my true love gave to me
Seven swans a-swimming.

Day 7: EXPLAIN PLAN lies (Day 6: The execution plan is a tree)(Day 8: Statistics are a double-edged sword)

An enduring Oracle myth is that EXPLAIN PLAN and AUTOTRACE show the execution plan. However, the only way to find the right query plan is to actually execute the query and get the execution plan from V$SQL_PLAN using DBMS_XPLAN.DISPLAY_CURSOR or your own custom query. The following query lists all employees whose IDs are greater than the value of the bind variable. EXPLAIN PLAN indicates that the primary key index will be used. If we run the query with AUTOTRACE turned on, it appears to confirm that the primary key index was used.

variable b1 number;

exec :b1 := 0;

explain plan for
select * from employees
where employee_id > :b1;

select * from table(dbms_xplan.display);

Plan hash value: 603312277

---------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |               |     5 |   345 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| EMPLOYEES     |     5 |   345 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | EMP_EMP_ID_PK |     2 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("EMPLOYEE_ID">TO_NUMBER(:B1))

set autotrace on

select * from employees
where employee_id > :b1;

Plan hash value: 603312277

---------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |               |     5 |   345 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| EMPLOYEES     |     5 |   345 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | EMP_EMP_ID_PK |     2 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("EMPLOYEE_ID">TO_NUMBER(:B1))

Statistics
----------------------------------------------------------
          8  recursive calls
          0  db block gets
         16  consistent gets
          6  physical reads
          0  redo size
       9455  bytes sent via SQL*Net to client
        496  bytes received via SQL*Net from client
          9  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        107  rows processed

set autotrace off

Let’s search the shared pool for our query using the plan hash value. Surprisingly, we don’t see our query. All we see is two invocations of EXPLAIN PLAN. One of them was caused by AUTOTRACE; that is, AUTOTRACE invokes EXPLAIN PLAN under the covers. But neither of them produced the right query plan. There are several reasons why the plans produced by EXPLAIN PLAN could be different from those actually used at execution time; refer to Tom Kyte’s explanation.

select sql_id, sql_text from v$sql
where plan_hash_value=603312277;

SQL_ID        SQL_TEXT
------------- ----------------------------------------------------------------
0duyr8c6w8xmk EXPLAIN PLAN SET STATEMENT_ID='PLUS13510305' FOR select * from e
              mployees where employee_id > :b1

3g87rd98f6ra2 explain plan for select * from employees where employee_id > :b1

Let’s instead search the shared pool for our query using the query text itself. If we check its query plan using DBMS_XPLAN.DISPLAY_CURSOR, we find that a full table scan was performed.

select sql_id, sql_text from v$sql
where sql_text like '%select * from employees%';

SQL_ID        SQL_TEXT
------------- ----------------------------------------------------------------
0duyr8c6w8xmk EXPLAIN PLAN SET STATEMENT_ID='PLUS13510305' FOR select * from e
              mployees where employee_id > :b1

bycfx5b3v5v33 select sql_id, sql_text from v$sql where sql_text like '%select
              * from employees%'

farrvwg0tqpbq select * from employees where employee_id > :b1
3g87rd98f6ra2 explain plan for select * from employees where employee_id > :b1

select * from table(dbms_xplan.display_cursor('farrvwg0tqpbq', 0, 'typical iostats last +peeked_binds'));

SQL_ID  farrvwg0tqpbq, child number 0
-------------------------------------
select * from employees where employee_id > :b1

Plan hash value: 1445457117

--------------------------------------------------------------------------------
| Id  | Operation         | Name      | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           |        |       |     3 (100)|          |
|*  1 |  TABLE ACCESS FULL| EMPLOYEES |    107 |  7383 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("EMPLOYEE_ID">:B1)

Note
-----
   - Warning: basic plan statistics not available. These are only collected when:
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level

Now we have the right query plan. However, a query plan without timings for each step is quite useless for query tuning; that is, we need the rowsource execution statistics.

alter session set "_rowsource_execution_statistics"=true;

select * from employees
where employee_id > :b1;

select * from table(dbms_xplan.display_cursor(null, null, 'typical iostats last +peeked_binds'));
SQL_ID  farrvwg0tqpbq, child number 1
-------------------------------------
select * from employees where employee_id > :b1

Plan hash value: 1445457117

-------------------------------------------------------------------------------------------------------------------------
| Id  | Operation         | Name      | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           |      1 |        |       |     3 (100)|          |    107 |00:00:00.01 |      14 |
|*  1 |  TABLE ACCESS FULL| EMPLOYEES |      1 |    107 |  7383 |     3   (0)| 00:00:01 |    107 |00:00:00.01 |      14 |
-------------------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("EMPLOYEE_ID">:B1)

Much better. However, it would be nice if the parent ID was listed for each step and the execution times were not cumulative. For that, you can always write your own custom query against V$SQL_PLAN_STATISTICS_ALL.

set linesize 250
set pagesize 1000
column "Operation" format a30
column "Name" format a30
column "A-time" format 999,999.990

WITH plan_table AS
(
  SELECT
    id,
    parent_id,
    object_name,
    operation,
    options,
    last_starts,
    last_elapsed_time / 1000000 AS last_elapsed_time,
    cardinality,
    last_output_rows,
    last_cr_buffer_gets + last_cu_buffer_gets AS last_buffer_gets,
    last_disk_reads
  FROM
    v$sql_plan_statistics_all
  WHERE
    sql_id = '&sql_id'
    AND child_number = &child_number
),
deltas AS
(
  SELECT
    t1.id,
    t1.last_elapsed_time - NVL(SUM(t2.last_elapsed_time),0) AS delta_elapsed_time,
    t1.last_buffer_gets - NVL(SUM(t2.last_buffer_gets),0) AS delta_buffer_gets,
    t1.last_disk_reads - NVL(SUM(t2.last_disk_reads),0) AS delta_disk_reads
  FROM
    plan_table t1
    LEFT OUTER JOIN plan_table t2
    ON t1.id = t2.parent_id
  GROUP BY
    t1.id,
    t1.last_elapsed_time,
    t1.last_buffer_gets,
    t1.last_disk_reads
)
SELECT
  parent_id AS "Parent Id",
  id AS "Id",
  lpad(' ',level-1)||operation AS "Operation",
  object_name AS "Name",
  last_starts AS "Starts",
  last_output_rows AS "A-Rows",
  delta_elapsed_time AS "A-Time",
  delta_buffer_gets AS "Buffers",
  delta_disk_reads AS "Reads"
FROM
  (
    SELECT
      plan_table.id,
      plan_table.parent_id,
      plan_table.object_name,
      plan_table.operation,
      plan_table.options,
      plan_table.last_starts,
      plan_table.last_elapsed_time,
      plan_table.cardinality,
      plan_table.last_output_rows,
      plan_table.last_buffer_gets,
      plan_table.last_disk_reads,
      deltas.delta_elapsed_time,
      deltas.delta_buffer_gets,
      deltas.delta_disk_reads
    FROM
      plan_table,
      deltas
    WHERE
      plan_table.id = deltas.id
  )
CONNECT BY prior id = parent_id
START WITH id = 0
ORDER BY id;

 Parent Id         Id Operation                      Name                               Starts     A-Rows       A-Time    Buffers      Reads
---------- ---------- ------------------------------ ------------------------------ ---------- ---------- ------------ ---------- ----------
                    0 SELECT STATEMENT                                                       1        107         .000          0          0
         0          1  TABLE ACCESS                  EMPLOYEES                               1        107         .000         14          0

P.S. Watch this fascinating YouTube video Rewriting SQL Queries for Performance in 9 Minutes by Stephane Faroult in which he makes a good argument that execution plans should not be the first thing to look at when a query does not perform well. He argues if you write high-quality SQL queries and your tables are well indexed, you can be reasonably confident that your queries will perform reasonably well. The analogy he gives is the problem of translating from one language to another using computer software; instead of constantly wondering how the language translation engine works and why it is producing poor-quality output, focus instead on writing well-structured and unambiguous input for the engine.


Day 6: The execution plan is a tree

Day 8: Statistics are a double-edged sword

Categories: DBA, Oracle, SQL
  1. No comments yet.
  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: