Home > Oracle, SQL > Explaining The EXPLAIN PLAN Using Pictures

Explaining The EXPLAIN PLAN Using Pictures


An Oracle EXPLAIN PLAN can be terribly hard to understand. Oracle does not tell us the order in which steps are executed and we must figure it out ourselves using the Oh so subtle indentation of operation names. It doesn’t help that the Oracle documentation incorrectly states that “The execution order in EXPLAIN PLAN output begins with the line that is the furthest indented to the right.” Another problem is that the execution metrics such as A-Time, Buffers, Reads, and Writes are cumulative. If you haven’t felt the pain recently, read the following query plan and try to figure out the order in which the steps are executed and the most expensive step.

--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name     | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |          |      1 |        |       |   795 (100)|          |      1 |00:00:03.06 |    2880 |   2393 |
|   1 |  SORT AGGREGATE              |          |      1 |      1 |   144 |            |          |      1 |00:00:03.06 |    2880 |   2393 |
|*  2 |   HASH JOIN RIGHT OUTER      |          |      1 |   2783 |   391K|   795   (2)| 00:00:10 |   2781 |00:00:03.06 |    2880 |   2393 |
|   3 |    INDEX FULL SCAN           | I_USER2  |      1 |     94 |   376 |     1   (0)| 00:00:01 |     94 |00:00:00.01 |       1 |      0 |
|*  4 |    HASH JOIN OUTER           |          |      1 |   2783 |   380K|   794   (2)| 00:00:10 |   2781 |00:00:03.03 |    2879 |   2393 |
|*  5 |     HASH JOIN                |          |      1 |   2783 |   358K|   735   (2)| 00:00:09 |   2781 |00:00:02.39 |    2665 |   2393 |
|   6 |      INDEX FULL SCAN         | I_USER2  |      1 |     94 |   376 |     1   (0)| 00:00:01 |     94 |00:00:00.01 |       1 |      0 |
|*  7 |      HASH JOIN               |          |      1 |   2783 |   347K|   733   (1)| 00:00:09 |   2781 |00:00:02.36 |    2664 |   2393 |
|*  8 |       HASH JOIN OUTER        |          |      1 |   2783 |   317K|   482   (1)| 00:00:06 |   2783 |00:00:01.55 |    1756 |   1487 |
|*  9 |        HASH JOIN RIGHT OUTER |          |      1 |   2783 |   304K|   423   (1)| 00:00:06 |   2783 |00:00:00.75 |    1542 |   1359 |
|  10 |         TABLE ACCESS FULL    | SEG$     |      1 |   5695 | 62645 |    47   (0)| 00:00:01 |   5735 |00:00:00.02 |     171 |      0 |
|* 11 |         HASH JOIN            |          |      1 |   2783 |   274K|   376   (1)| 00:00:05 |   2783 |00:00:00.66 |    1371 |   1359 |
|  12 |          MERGE JOIN CARTESIAN|          |      1 |      7 |   497 |     5  (20)| 00:00:01 |      7 |00:00:00.03 |       9 |      0 |
|* 13 |           HASH JOIN          |          |      1 |      1 |    68 |     1 (100)| 00:00:01 |      1 |00:00:00.03 |       0 |      0 |
|* 14 |            FIXED TABLE FULL  | X$KSPPI  |      1 |      1 |    55 |     0   (0)|          |      1 |00:00:00.01 |       0 |      0 |
|  15 |            FIXED TABLE FULL  | X$KSPPCV |      1 |    100 |  1300 |     0   (0)|          |   2394 |00:00:00.01 |       0 |      0 |
|  16 |           BUFFER SORT        |          |      1 |      7 |    21 |     5  (20)| 00:00:01 |      7 |00:00:00.01 |       9 |      0 |
|  17 |            TABLE ACCESS FULL | TS$      |      1 |      7 |    21 |     4   (0)| 00:00:01 |      7 |00:00:00.01 |       9 |      0 |
|* 18 |          TABLE ACCESS FULL   | TAB$     |      1 |   2783 | 83490 |   371   (1)| 00:00:05 |   2783 |00:00:00.60 |    1362 |   1359 |
|  19 |        INDEX FAST FULL SCAN  | I_OBJ1   |      1 |  73373 |   358K|    58   (0)| 00:00:01 |  73418 |00:00:00.30 |     214 |    128 |
|* 20 |       TABLE ACCESS FULL      | OBJ$     |      1 |  73373 |   788K|   250   (2)| 00:00:03 |  73416 |00:00:00.26 |     908 |    906 |
|  21 |     INDEX FAST FULL SCAN     | I_OBJ1   |      1 |  73373 |   573K|    58   (0)| 00:00:01 |  73418 |00:00:00.16 |     214 |      0 |
--------------------------------------------------------------------------------------------------------------------------------------------

Here is a graphical version of the above query plan. To increase the size, you can click on it and zoom in using your browser. We see that the steps are executed in the order 3, 6, 10, 14, 15, 13, 17, 16, 12, 18, 11, 9, 19, 8, 20, 7, 5, 21, 4, 2, 1, and 0 and the most expensive step is the one with Id 18, accounting for 20% of the elapsed time and 47% of the buffer gets.

I used the Graphviz tool to produce the above picture. The following SQL*Plus script generates the necessary Graphviz commands. It prompts for a SQL_ID and CHILD_NUMBER, retrieves the basic plan information from V$SQL_PLAN_STATISTICS_ALL, determines the order in which the steps are executed, computes the execution time for each step, and labels the nodes in the graph. It’s a longish script but I’ve modularized it using common table expressions and provided a lot of inline comments. I hope you find it useful. Feedback and suggestions are welcome.

Happy Holidays.

P.S. The SQL query which resulted in the above plan was “SELECT * FROM dba_tables.” Refer to Deep Left Trees, Deep Right Trees, and Bushy Trees! Oh, My! for more examples of graphical query plans.

/*

Copyright 2010 Iggy Fernandez

This program is free software: you can redistribute it and/or modify
it under the terms of the GNU General Public License as published by
the Free Software Foundation, either version 3 of the License, or
(at your option) any later version.

The purpose of this SQL*Plus script is to generate a Graphviz
program that can draw a tree-structure graphical version of a query
plan. It prompts for a SQL_ID and CHILD_NUMBER. The following basic
data items are first obtained from V$SQL_PLAN_STATISTICS_ALL:

  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

The following items are then computed from the basic data:

  execution_sequence#
  delta_elapsed_time
  delta_buffer_gets
  delta_disk_reads
  delta_percentage_elapsed_time
  delta_percentage_buffer_gets
  delta_percentage_disk_reads
  last_percentage_elapsed_time
  last_percentage_buffer_gets
  last_percentage_disk_reads

Graphviz commands are then spooled to plan.dot. If Graphviz has been
installed, the following command can be used to produce graphical
output.

  dot -Tjpg -oplan.jpg plan.dot

As an example, the following query generates a list of employees
whose salaries are higher than their respective managers.

SELECT
  emp.employee_id AS emp_id,
  emp.salary AS emp_salary
FROM
  employees emp
WHERE EXISTS (
  SELECT
    *
  FROM
    employees mgr
  WHERE
    emp.manager_id = mgr.employee_id
  AND
    emp.salary > mgr.salary
);

Here is an abbreviated version of the traditional tabular query
plan.

----------------------------------------
| Id  | Operation          | Name      |
----------------------------------------
|   0 | SELECT STATEMENT   |           |
|   1 |  HASH JOIN SEMI    |           |
|   2 |   TABLE ACCESS FULL| EMPLOYEES |
|   3 |   TABLE ACCESS FULL| EMPLOYEES |
----------------------------------------

And here is an abbreviated version of the Graphviz program produced
by this script.

digraph EnhancedPlan {graph[ordering="out"];node[fontname=Arial fontsize=8];
"0" [label="Step 4 (Id 0)\nSELECT STATEMENT", shape=plaintext];
"1" [label="Step 3 (Id 1)\nHASH JOIN SEMI", shape=plaintext];
"2" [label="Step 1 (Id 2)\nTABLE ACCESS FULL EMPLOYEES", shape=plaintext];
"3" [label="Step 2 (Id 3)\nTABLE ACCESS FULL EMPLOYEES", shape=plaintext];
"0"->"1" [dir=back];
"1"->"2" [dir=back];
"1"->"3" [dir=back];
}

*/
--------------------------------------------------------------------------------

-- SQL*Plus settings

SET linesize 1000
SET trimspool on
SET pagesize 0
SET echo off
SET heading off
SET feedback off
SET verify off
SET time off
SET timing off
SET sqlblanklines on

SPOOL plan.dot

--------------------------------------------------------------------------------

-- First retrieve the basic data from V$SQL_PLAN_STATISTICS_ALL.
-- Modify this subquery if you want data from a different source.

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

),

--------------------------------------------------------------------------------

-- Determine the order in which steps are actually executed

execution_sequence AS

(

  SELECT

    id,
    ROWNUM AS execution_sequence#

  FROM

    plan_table pt1

  START WITH

    -- Start with the leaf nodes
    NOT EXISTS (
      SELECT *
      FROM plan_table pt2
      WHERE pt2.parent_id = pt1.id
    )

  CONNECT BY

    -- Connect to the parent node
    pt1.id = PRIOR pt1.parent_id
    -- if the prior node was the oldest sibling
    AND PRIOR pt1.id >= ALL(
      SELECT pt2.id
      FROM plan_table pt2
      WHERE pt2.parent_id = pt1.id
    )

  -- Process the leaf nodes from left to right
  ORDER SIBLINGS BY pt1.id

),

--------------------------------------------------------------------------------

-- Calculate deltas for elapsed time, buffer gets, and disk reads

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

),

--------------------------------------------------------------------------------

-- Join the results of the previous subqueries

enhanced_plan_table AS

(

  SELECT

    -- Items from the plan_table subquery

    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,

    -- Items from the execution_sequence subquery

    execution_sequence.execution_sequence#,

    -- Items from the deltas subquery

    deltas.delta_elapsed_time,
    deltas.delta_buffer_gets,
    deltas.delta_disk_reads,

    -- Computed percentages

    CASE
      WHEN (SUM(deltas.delta_elapsed_time) OVER () = 0)
      THEN (100)
      ELSE (100 * deltas.delta_elapsed_time / SUM(deltas.delta_elapsed_time) OVER ())
    END AS delta_percentage_elapsed_time,

    CASE
      WHEN (SUM(deltas.delta_buffer_gets) OVER () = 0)
      THEN (100)
      ELSE (100 * deltas.delta_buffer_gets / SUM(deltas.delta_buffer_gets) OVER ())
    END AS delta_percentage_buffer_gets,

    CASE
      WHEN (SUM(deltas.delta_disk_reads) OVER () = 0)
      THEN (100)
      ELSE (100 * deltas.delta_disk_reads / SUM(deltas.delta_disk_reads) OVER ())
    END AS delta_percentage_disk_reads,

    CASE
      WHEN (SUM(deltas.delta_elapsed_time) OVER () = 0)
      THEN (100)
      ELSE (100 * plan_table.last_elapsed_time / SUM(deltas.delta_elapsed_time) OVER ())
    END AS last_percentage_elapsed_time,

    CASE
      WHEN (SUM(deltas.delta_buffer_gets) OVER () = 0)
      THEN (100)
      ELSE (100 * plan_table.last_buffer_gets / SUM(deltas.delta_buffer_gets) OVER ())
    END AS last_percentage_buffer_gets,

    CASE
      WHEN (SUM(deltas.delta_disk_reads) OVER () = 0)
      THEN (100)
      ELSE (100 * plan_table.last_disk_reads / SUM(deltas.delta_disk_reads) OVER ())
    END AS last_percentage_disk_reads

  FROM

    plan_table,
    execution_sequence,
    deltas

  WHERE

    plan_table.id = execution_sequence.id
    AND plan_table.id = deltas.id

  -- Order the results for cosmetic purposes
  ORDER BY plan_table.id

)

--------------------------------------------------------------------------------

-- Begin THE Graphviz program

SELECT

  'digraph EnhancedPlan {'
  || 'graph[ordering="out"];'
  || 'node[fontname=Arial fontsize=8];' AS command

FROM DUAL

--------------------------------------------------------------------------------

-- Label the nodes

UNION ALL SELECT

  '"' || id || '" [label="'

  -- Line 1: Execution Sequence # and Id

  || 'Step ' || execution_sequence#
  || ' (Id ' || id || ')'
  || '\n'

  -- Line 2: Operations, options, object name, and starts

  || operation

  || CASE
       WHEN (options IS NULL)
       THEN ('')
       ELSE (' ' || options)
     END

  || CASE
       WHEN (object_name IS NULL)
       THEN ('')
       ELSE (' ' || object_name)
     END

  || CASE
       WHEN (last_starts > 1)
       THEN (' (Starts = ' || last_starts || ')')
       ELSE ('')
     END

  || '\n'

  -- Line 3: Delta elapsed time and cumulative elapsed time

  || 'Delta Elapsed = '
  || CASE
       WHEN (delta_elapsed_time IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_elapsed_time, '999,999,990.00')) || 's')
     END

  || ' ('
  || CASE
       WHEN (delta_percentage_elapsed_time IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_percentage_elapsed_time, '990')) || '%')
     END
  || ')'

  || ' Cum Elapsed = '
  || CASE
       WHEN (last_elapsed_time IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(last_elapsed_time, '999,999,990.00')) || 's')
     END

  || ' ('
  || CASE
       WHEN (last_percentage_elapsed_time IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(last_percentage_elapsed_time, '990')) || '%')
     END
  || ')'

  || '\n'

  -- Line 4: Delta buffer gets and cumulative buffer gets

  || 'Delta Buffer Gets = '
  || CASE
       WHEN (delta_buffer_gets IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_buffer_gets, '999,999,999,999,990')))
     END

  || ' ('
  || CASE
       WHEN (delta_percentage_buffer_gets IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_percentage_buffer_gets, '990')) || '%')
     END
  || ')'

  || ' Cum Buffer Gets = '
  || CASE
       WHEN (last_buffer_gets IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(last_buffer_gets, '999,999,999,999,990')))
     END

  || ' ('
  || CASE
       WHEN (last_percentage_buffer_gets IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(last_percentage_buffer_gets, '990')) || '%')
     END
  || ')'

  || '\n'

  -- Line 5: Delta disk reads and cumulative disk reads

  || 'Delta Disk Reads = '
  || CASE
       WHEN (delta_disk_reads IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_disk_reads, '999,999,999,999,990')))
     END

  || ' ('
  || CASE
       WHEN (delta_percentage_disk_reads IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(delta_percentage_disk_reads, '990')) || '%')
     END
  || ')'

  || ' Cum Disk Reads = '
  || CASE
       WHEN (last_disk_reads IS NULL)
       THEN ('?')
       ELSE (TRIM(TO_CHAR(last_disk_reads, '999,999,999,999,990')))
      END

  || ' ('
  || CASE
       WHEN (last_percentage_disk_reads IS NULL)
        THEN ('?')
       ELSE (TRIM(TO_CHAR(last_percentage_disk_reads, '990')) || '%')
     END
  || ')'

  || '\n'

  -- Line 6: Estimated rows and actual rows

  || 'Estimated Rows = '
  || CASE
       WHEN (cardinality IS NULL)
       THEN '?'
       ELSE (TRIM(TO_CHAR(cardinality, '999,999,999,999,990')))
     END

  || ' Actual Rows = '
  || CASE
       WHEN (last_output_rows IS NULL)
       THEN '?'
       ELSE (TRIM(TO_CHAR(last_output_rows, '999,999,999,999,990')))
     END

  || '\n'

  || '", shape=plaintext];' AS command

FROM enhanced_plan_table

--------------------------------------------------------------------------------

-- Connect the nodes

UNION ALL SELECT '"' || parent_id || '"->"' || id || '" [dir=back];' AS command
FROM plan_table
START WITH parent_id = 0
CONNECT BY parent_id = PRIOR id

--------------------------------------------------------------------------------

-- End THE Graphviz program

UNION ALL SELECT '}' AS command
FROM DUAL;

--------------------------------------------------------------------------------

SPOOL off

Deep Left Trees, Deep Right Trees, and Bushy Trees! Oh, My!

About these ads
Categories: Oracle, SQL
  1. November 26, 2010 at 5:32 pm | #1

    Hi.

    The documentation is correct. You’ve misunderstood how to read the execution plan. If you want to confirm how to read the plan, use the ORDERED hint which will force the table order to match the order of the tables in FROM clause. That way you will easily see where the first table is processed, and sure enough, it will be where the documentation says it should be.

    Incidentally, your diagram looks correct, but I guess you are reading that incorrectly also.

    Cheers

    Tim…

  2. November 26, 2010 at 8:10 pm | #2

    Tim Hall is correct that adding an ORDERED hint will change the order of the row sources, possibly so that it looks like the most indented row sources are the starting point for the execution, as stated in the Oracle documentation. For example, if you look at the SQL statement and execution on the following page that is titled as “Determining how many of each part was ordered in the last 90 days” (roughly half way down the page)
    http://hoopercharles.wordpress.com/2010/11/24/different-performance-from-standard-edition-and-enterprise-edition-4
    enabling AUTOTRACE TRACEONLY EXPLAIN and then submitting the SQL statement generates an execution plan that looks like this:

    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 2798666738
     
    -------------------------------------------------------------------------------------------
    | Id  | Operation             | Name      | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT      |           |   172K|    12M|       | 25911   (2)| 00:03:28 |
    |   1 |  HASH GROUP BY        |           |   172K|    12M|    55M| 25911   (2)| 00:03:28 |
    |*  2 |   FILTER              |           |       |       |       |            |          |
    |*  3 |    HASH JOIN          |           |   694K|    48M|  3216K| 21791   (2)| 00:02:55 |
    |   4 |     TABLE ACCESS FULL | PARTS     | 99694 |  2044K|       |   394   (1)| 00:00:04 |
    |*  5 |     HASH JOIN         |           |   694K|    34M|       | 20823   (2)| 00:02:47 |
    |*  6 |      TABLE ACCESS FULL| PO_HEADER | 28056 |   767K|       |  1068   (4)| 00:00:09 |
    |   7 |      TABLE ACCESS FULL| PO_LINE   |    12M|   279M|       | 19697   (2)| 00:02:38 |
    -------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       2 - filter(TRUNC(SYSDATE@!-90)<=TRUNC(SYSDATE@!))
       3 - access("POL"."PART_ID"="P"."PART_ID")
       5 - access("PO"."PURC_ORDER_ID"="POL"."PURC_ORDER_ID")
       6 - filter("PO"."ORDER_DATE"<=TRUNC(SYSDATE@!) AND
                  "PO"."ORDER_DATE">=TRUNC(SYSDATE@!-90))
    

    With the above execution plan, Iggy’s statement suggests that Oracle’s runtime engine will start at the first line without a child, which is the PARTS table. The documentation states that the excution will begin with the hash join of the PO_HEADER and the PO_LINE tables. Now let’s change the order of the tables so that it matches Iggy’s suggestion and then add an ORDERED hint:

    Plan hash value: 554536386
     
    -------------------------------------------------------------------------------------------
    | Id  | Operation             | Name      | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT      |           |   172K|    12M|       | 30693   (2)| 00:04:06 |
    |   1 |  HASH GROUP BY        |           |   172K|    12M|    55M| 30693   (2)| 00:04:06 |
    |*  2 |   FILTER              |           |       |       |       |            |          |
    |*  3 |    HASH JOIN          |           |   694K|    48M|       | 26574   (2)| 00:03:33 |
    |*  4 |     TABLE ACCESS FULL | PO_HEADER | 28056 |   767K|       |  1068   (4)| 00:00:09 |
    |*  5 |     HASH JOIN         |           |    12M|   523M|  3216K| 25447   (2)| 00:03:24 |
    |   6 |      TABLE ACCESS FULL| PARTS     | 99694 |  2044K|       |   394   (1)| 00:00:04 |
    |   7 |      TABLE ACCESS FULL| PO_LINE   |    12M|   279M|       | 19697   (2)| 00:02:38 |
    -------------------------------------------------------------------------------------------
     
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       2 - filter(TRUNC(SYSDATE@!-90)<=TRUNC(SYSDATE@!))
       3 - access("PO"."PURC_ORDER_ID"="POL"."PURC_ORDER_ID")
       4 - filter("PO"."ORDER_DATE"<=TRUNC(SYSDATE@!) AND
                  "PO"."ORDER_DATE">=TRUNC(SYSDATE@!-90))
       5 - access("POL"."PART_ID"="P"."PART_ID")
    

    Now, according to Iggy’s blog article the execution actually begins at the PO_HEADER table, rather than the PARTS table.

    So, is Iggy (and Tanel Poder who made essentially the same statement at the Michigan OakTable Symposium) incorrect? Only one way to find out:

    SQL> ALTER SYSTEM FLUSH BUFFER_CACHE;
    
    System altered.
    
    SQL> ALTER SYSTEM FLUSH BUFFER_CACHE;
    
    System altered.
    
    SQL> SET ARRAYSIZE 1000
    SQL> SET AUTOTRACE TRACEONLY STATISTICS
    SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SELECT_FROM_TABLES';
    
    Session altered.
    
    SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
    
    Session altered.
    
    SQL> SELECT
      2    PO.VENDOR_ID,
      3    P.PRODUCT_CODE,
      4    P.STOCK_UM,
      5    SUM(POL.ORDER_QTY) ORDER_QTY
      6  FROM
      7    PO_HEADER PO,
      8    PO_LINE POL,
      9    PARTS P
     10  WHERE
     11    PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
     12    AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
     13    AND POL.PART_ID=P.PART_ID
     14  GROUP BY
     15    PO.VENDOR_ID,
     16    P.PRODUCT_CODE,
     17    P.STOCK_UM;
    
    2245 rows selected.
    

    Taking a look in the trace file:

    PARSING IN CURSOR #7 len=323 dep=0 uid=286 oct=3 lid=286 tim=185409497003 hv=1875222938 ad='467ae3528' sqlid='8xcx0k9rwb8cu'
    SELECT
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM,
      SUM(POL.ORDER_QTY) ORDER_QTY
    FROM
      PO_HEADER PO,
      PO_LINE POL,
      PARTS P
    WHERE
      PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
      AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
      AND POL.PART_ID=P.PART_ID
    GROUP BY
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM
    END OF STMT
    PARSE #7:c=0,e=3668,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2798666738,tim=185409497003
    EXEC #7:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2798666738,tim=185409497134
    WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=185409497172
    WAIT #7: nam='db file sequential read' ela= 492 file#=1 block#=515584 blocks=1 obj#=82052 tim=185409497803
    WAIT #7: nam='db file scattered read' ela= 491 file#=1 block#=515585 blocks=7 obj#=82052 tim=185409498413
    WAIT #7: nam='db file scattered read' ela= 451 file#=1 block#=515656 blocks=8 obj#=82052 tim=185409500510
    WAIT #7: nam='db file scattered read' ela= 617 file#=1 block#=515664 blocks=8 obj#=82052 tim=185409501284
    WAIT #7: nam='db file scattered read' ela= 396 file#=1 block#=515672 blocks=8 obj#=82052 tim=185409501909
    ...
    WAIT #7: nam='db file scattered read' ela= 4094 file#=1 block#=522880 blocks=128 obj#=82052 tim=185409662106
    WAIT #7: nam='db file scattered read' ela= 677 file#=1 block#=523008 blocks=125 obj#=82052 tim=185409664394
    WAIT #7: nam='db file sequential read' ela= 576 file#=1 block#=536704 blocks=1 obj#=82062 tim=185409666470
    WAIT #7: nam='db file scattered read' ela= 555 file#=1 block#=536705 blocks=7 obj#=82062 tim=185409667136
    WAIT #7: nam='db file scattered read' ela= 598 file#=1 block#=536752 blocks=8 obj#=82062 tim=185409668862
    ...
    WAIT #7: nam='db file scattered read' ela= 379 file#=1 block#=558336 blocks=128 obj#=82062 tim=185410070973
    WAIT #7: nam='db file scattered read' ela= 384 file#=1 block#=558464 blocks=107 obj#=82062 tim=185410072944
    WAIT #7: nam='db file sequential read' ela= 332 file#=1 block#=96384 blocks=1 obj#=82069 tim=185410074862
    WAIT #7: nam='direct path read' ela= 289 file number=1 first dba=96385 block cnt=7 obj#=82069 tim=185410075669
    WAIT #7: nam='direct path read' ela= 354 file number=1 first dba=96456 block cnt=8 obj#=82069 tim=185410077862
    ...
    

    So, the execution of the query started with object ID 82052, then object ID 82062, and finally 82069. So, what are those objects?

    SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82052;
    
    OBJECT_NAME
    ---------------------------------------------------------------
    PARTS
    
    SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82062;
    
    OBJECT_NAME
    ---------------------------------------------------------------
    PO_HEADER
    
    SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82069;
    
    OBJECT_NAME
    ---------------------------------------------------------------
    PO_LINE
    

    The execution started at the first line without a child (PARTS table at ID 4), and then to the next line without a child (PO_HEADER table at ID 6) and then the last table (PO_LINE).

    Based on the contents of the 10046 trace file, it appears that Iggy is correct regarding the execution order.

  3. November 26, 2010 at 8:14 pm | #3

    The SQL statement with the ORDERED hint and the rearranged table order was mistakenly left out of the post. That SQL statement was as follows:

    SELECT /*+ ORDERED */
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM,
      SUM(POL.ORDER_QTY) ORDER_QTY
    FROM
      PARTS P,
      PO_LINE POL,
      PO_HEADER PO
    WHERE
      PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
      AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
      AND POL.PART_ID=P.PART_ID
    GROUP BY
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM;
    
  4. November 26, 2010 at 8:37 pm | #4

    One more using my sample data in Oracle Database 11.2.0.1 – is the ORDERED hint really behaving as one would expect.

    SELECT /*+ ORDERED */
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM,
      SUM(POL.ORDER_QTY) ORDER_QTY
    FROM
      PARTS P,
      PO_HEADER PO,
      PO_LINE POL
    WHERE
      PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
      AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
      AND POL.PART_ID=P.PART_ID
    GROUP BY
      PO.VENDOR_ID,
      P.PRODUCT_CODE,
      P.STOCK_UM;
    

    Based on the order of the tables in the FROM clause and the ORDERED hint, I would expect the PARTS table to be joined to the PO_HEADER (Cartesian product) and then the result joined to PO_LINE. What does AUTOTRACE show?

    Plan hash value: 1310306020
    
    ----------------------------------------------------------------------------------------------
    | Id  | Operation                | Name      | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    ----------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT         |           |   172K|  9935K|       |   127K  (1)| 00:17:04 |
    |   1 |  HASH GROUP BY           |           |   172K|  9935K|    38M|   127K  (1)| 00:17:04 |
    |   2 |   MERGE JOIN             |           |   561K|    31M|       |   124K  (1)| 00:16:39 |
    |   3 |    SORT JOIN             |           |  9860K|   291M|       |   123K  (1)| 00:16:29 |
    |   4 |     VIEW                 | VW_GBC_9  |  9860K|   291M|       |   123K  (1)| 00:16:29 |
    |   5 |      HASH GROUP BY       |           |  9860K|   423M|   657M|   123K  (1)| 00:16:29 |
    |*  6 |       FILTER             |           |       |       |       |            |          |
    |*  7 |        HASH JOIN         |           |    12M|   523M|  3216K| 25447   (2)| 00:03:24 |
    |   8 |         TABLE ACCESS FULL| PARTS     | 99694 |  2044K|       |   394   (1)| 00:00:04 |
    |   9 |         TABLE ACCESS FULL| PO_LINE   |    12M|   279M|       | 19697   (2)| 00:02:38 |
    |* 10 |    SORT JOIN             |           | 28056 |   767K|  2216K|  1251   (4)| 00:00:11 |
    |* 11 |     TABLE ACCESS FULL    | PO_HEADER | 28056 |   767K|       |  1068   (4)| 00:00:09 |
    ----------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       6 - filter(TRUNC(SYSDATE@!-90)<=TRUNC(SYSDATE@!))
       7 - access("POL"."PART_ID"="P"."PART_ID")
      10 - access("PO"."PURC_ORDER_ID"="ITEM_1")
           filter("PO"."PURC_ORDER_ID"="ITEM_1")
      11 - filter("PO"."ORDER_DATE"<=TRUNC(SYSDATE@!) AND
                  "PO"."ORDER_DATE">=TRUNC(SYSDATE@!-90))
    

    Autotrace show that the PARTS table is to be joined to the PO_LINE table and that result is then joined to PO_HEADER. A 10046 trace confirms that the plan order is followed:

    WAIT #3: nam='db file scattered read' ela= 514 file#=1 block#=515656 blocks=8 obj#=82052 tim=188212877914
    WAIT #3: nam='db file scattered read' ela= 620 file#=1 block#=515664 blocks=8 obj#=82052 tim=188212878680
    WAIT #3: nam='db file scattered read' ela= 437 file#=1 block#=515672 blocks=8 obj#=82052 tim=188212879260
    ...
    WAIT #3: nam='db file scattered read' ela= 86 file#=1 block#=523130 blocks=3 obj#=82052 tim=188213117527
    WAIT #3: nam='direct path read' ela= 504 file number=1 first dba=96385 block cnt=7 obj#=82069 tim=188213118286
    WAIT #3: nam='direct path read' ela= 322 file number=1 first dba=96496 block cnt=24 obj#=82069 tim=188213138029
    ...
    WAIT #3: nam='direct path read temp' ela= 392 file number=201 first dba=282358 block cnt=7 obj#=82069 tim=188228754707
    WAIT #3: nam='db file scattered read' ela= 483 file#=1 block#=536705 blocks=7 obj#=82062 tim=188228755317
    WAIT #3: nam='db file scattered read' ela= 528 file#=1 block#=536752 blocks=8 obj#=82062 tim=188228755980
    ...
    
  5. Iggy Fernandez
    November 26, 2010 at 9:01 pm | #5

    Thanks very much for the experimental verification, Charles. Nullius in verba.

  6. DanyC
    November 27, 2010 at 5:07 am | #6

    Very interesting subject!! It seems i can’t trust Oracle doc :)

    Thanks,
    Dani

  7. November 27, 2010 at 6:39 am | #7

    Iggy & Charles:

    My bad. When I read the post last night I thought you were discussing the join order. The way the documentation tells you to read the execution plan describes the order the joins take place and therefore the order in which the rowsources are “used”. I still believe this is correct.

    The point you guys are making is, the chronological order the rowsources are retrieved does not match the order they are used in the joins for all plans.

    Looking at the following two plans:

    (1)
    HASH JOIN
      TAB3
      HASH JOIN
        TAB1
        TAB2
    
    (2)
    HASH JOIN
      HASH JOIN
        TAB1
        TAB2
      TAB3

    In both cases the HASH JOIN between TAB1 & TAB2 happens first, so TAB1 and TAB2 are “used” before TAB3. Ignoring for the moment which set is used to build the hash table, the difference between them is that plan (1) retrieves the rowsources in the order TAB3, TAB1, TAB2 and plan (2) retrieves the rowsources in the order TAB1, TAB2, TAB3…

    This is what you are saying right?

    So row source retrieval is not always in the same order as rowsource use…

    Cheers

    Tim…

    PS. Sorry for not using real examples. I’m posting from my iPad. I’ve got find a place to charge my laptop… :)

  8. November 27, 2010 at 9:46 am | #8

    I’ve just read my comment back and I’m not really happy with the wording. Well, actually I’ve kinda bolloxed it up completely. Let’s try another (very brief) stab at it.

    The child join operation (deeper indent) is providing rows to feed the parent join operation (outer indent) . So the indent method described by the docs makes sense when describing the order of the join operations. It falls apart when describing the order of row source operations. I think that’s what I’m trying to say.

    I was talking to Jonathan Lewis at ODTUG about his presentation saying that being able to do this stuff and being able to communicate it are very different skills. I’ve just proved to myself again what I said to him at the time. I am incapable of communicating this stuff in any reasonable manner.

    Cheers

    Tim…

  9. November 27, 2010 at 10:01 am | #9

    Jonathan apparently commented on that quote from the documentation almost 6 years ago.
    http://www.freelists.org/post/oracle-l/Mysterious-FILTER-operation,11

    A Google search shows that quite a number of people believe that the quote is true.

    Dani,
    For the most part the Oracle documentation is correct, but every once in a while something slips through the cracks. It makes for a bit of a treasure hunt trying to find errors.

  10. November 27, 2010 at 6:34 pm | #10

    Great post and discussion! Its nice for me to take a refresher into the world of explain plans.

    Cheers,
    Ben

  11. Iggy Fernandez
    November 27, 2010 at 6:36 pm | #11

    Tim,

    I was scheduled to speak right after Jonathan’s session at the All India Oracle Users Group conference in Hyderabad and my session must have paled in comparison because the feedback was quite brutal. One attendee wrote “Im sure u will crack things when working @home.. But when giving public seminars needs log of ground work.”

    Certainly the “right to left, top to bottom” instructions provided in the Oracle documentation work perfectly with deep left trees and even with deep right trees but fall short in the case of bushy trees. Here’s a contrived example using the tables in the HR sample schema; it contains an unmergeable inline view.

    SELECT
      /*+
      LEADING(e j d)
      USE_NL(j)
      USE_NL(d)
      */
      e.first_name,
      e.last_name,
      e.salary,
      j.job_title,
      d.department_name,
      d.city,
      d.state_province,
      d.country_name,
      d.region_name
    FROM
      employees e,
      jobs j,
      (
        SELECT
        /*+
        NO_MERGE
        LEADING(d l c r)
        USE_NL(l)
        USE_NL(c)
        USE_NL(r)
        */
        d.department_id,
        d.department_name,
        l.city,
        l.state_province,
        c.country_name,
        r.region_name
      FROM
        departments d,
        locations l,
        countries c,
        regions r
      WHERE
        l.location_id = d.location_id
        AND c.country_id = l.country_id
        AND r.region_id = c.region_id
      ) d
    WHERE
      e.department_id = 90
      AND j.job_id = e.job_id
      AND d.department_id = e.department_id;
    

    Here is the query plan for the above query. The nodes are processed in the order 4, 3, 6, 5, 2, 12, 11, 14, 13, 10, 15, 9, 17, 16, 8, 7, 1, and 0. A picture is at http://iggyfernandez.files.wordpress.com/2010/11/bushy-tree.jpg.

    ---------------------------------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                        | Name              | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |
    ---------------------------------------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                 |                   |      1 |        |       |    14 (100)|          |      3 |00:00:00.20 |      26 |     32 |
    |   1 |  NESTED LOOPS                    |                   |      1 |      3 |   465 |    14   (0)| 00:00:01 |      3 |00:00:00.20 |      26 |     32 |
    |   2 |   NESTED LOOPS                   |                   |      1 |      3 |   174 |     5   (0)| 00:00:01 |      3 |00:00:00.13 |       9 |     11 |
    |   3 |    TABLE ACCESS BY INDEX ROWID   | EMPLOYEES         |      1 |      3 |    93 |     2   (0)| 00:00:01 |      3 |00:00:00.06 |       4 |      2 |
    |*  4 |     INDEX RANGE SCAN             | EMP_DEPARTMENT_IX |      1 |      3 |       |     1   (0)| 00:00:01 |      3 |00:00:00.02 |       2 |      1 |
    |   5 |    TABLE ACCESS BY INDEX ROWID   | JOBS              |      3 |      1 |    27 |     1   (0)| 00:00:01 |      3 |00:00:00.06 |       5 |      9 |
    |*  6 |     INDEX UNIQUE SCAN            | JOB_ID_PK         |      3 |      1 |       |     0   (0)|          |      3 |00:00:00.02 |       2 |      1 |
    |   7 |   VIEW                           |                   |      3 |      1 |    97 |     3   (0)| 00:00:01 |      3 |00:00:00.08 |      17 |     21 |
    |   8 |    NESTED LOOPS                  |                   |      3 |      1 |    71 |     3   (0)| 00:00:01 |      3 |00:00:00.08 |      17 |     21 |
    |   9 |     NESTED LOOPS                 |                   |      3 |      1 |    57 |     2   (0)| 00:00:01 |      3 |00:00:00.05 |      12 |     12 |
    |  10 |      NESTED LOOPS                |                   |      3 |      1 |    42 |     2   (0)| 00:00:01 |      3 |00:00:00.04 |      10 |     11 |
    |  11 |       TABLE ACCESS BY INDEX ROWID| DEPARTMENTS       |      3 |      1 |    19 |     1   (0)| 00:00:01 |      3 |00:00:00.01 |       5 |      2 |
    |* 12 |        INDEX UNIQUE SCAN         | DEPT_ID_PK        |      3 |      1 |       |     0   (0)|          |      3 |00:00:00.01 |       2 |      1 |
    |  13 |       TABLE ACCESS BY INDEX ROWID| LOCATIONS         |      3 |      1 |    23 |     1   (0)| 00:00:01 |      3 |00:00:00.02 |       5 |      9 |
    |* 14 |        INDEX UNIQUE SCAN         | LOC_ID_PK         |      3 |      1 |       |     0   (0)|          |      3 |00:00:00.01 |       2 |      1 |
    |* 15 |      INDEX UNIQUE SCAN           | COUNTRY_C_ID_PK   |      3 |      1 |    15 |     0   (0)|          |      3 |00:00:00.01 |       2 |      1 |
    |  16 |     TABLE ACCESS BY INDEX ROWID  | REGIONS           |      3 |      1 |    14 |     1   (0)| 00:00:01 |      3 |00:00:00.02 |       5 |      9 |
    |* 17 |      INDEX UNIQUE SCAN           | REG_ID_PK         |      3 |      1 |       |     0   (0)|          |      3 |00:00:00.02 |       2 |      1 |
    ---------------------------------------------------------------------------------------------------------------------------------------------------------
    

    Cheers,

    Iggy

  12. November 28, 2010 at 2:48 pm | #12

    Yes, you are correct. :)

    Cheers

    Tim…

  1. November 29, 2010 at 8:18 am | #1
  2. December 5, 2010 at 10:11 pm | #2

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

Follow

Get every new post delivered to your Inbox.

Join 668 other followers

%d bloggers like this: