Explain Plan Lies, Autotrace Lies, TKPROF Lies, What is the Plan?

11 01 2010

January 11, 2010

As some of you might be aware, EXPLAIN PLAN will occasionally show the wrong execution plan for a SQL statement.  SQL*Plus’ AUTOTRACE feature experiences a similar problem with generating accurate plans from time to time, especially when the SQL statement uses bind variables.  Did you know that TKPROF may also show the wrong execution plan from time to time?  I set up a simple test case to demonstrate this behavior.

The test case tables:

CREATE TABLE T1(
  C1 NUMBER,
  C2 VARCHAR2(255),
  PRIMARY KEY (C1));

CREATE TABLE T2(
  C1 NUMBER,
  C2 VARCHAR2(255),
  PRIMARY KEY (C1));

INSERT INTO
  T1
SELECT
  ROWNUM,
  LPAD('A',255,'A')
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10000) V1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=30) V2;

INSERT INTO
  T2
SELECT
  ROWNUM,
  LPAD('A',255,'A')
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10000) V1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=30) V2;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)

The above creates two tables, each with 300,000 rows with a primary key column (thus an index exists for the column), and a second column that acts as padding to make the row longer (to discourage full table scans).

The test script that I built looks like this:

ALTER SESSION SET STATISTICS_LEVEL='ALL';

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER

SET AUTOTRACE TRACEONLY EXPLAIN
SET LINESIZE 150
SET PAGESIZE 2000
SET ARRAYSIZE 100

SPOOL DIFF_EXPLAIN_PLAN_TEST.TXT

EXEC :N1:=1
EXEC :N2:=2

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=10

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=100

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=1000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=10000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=100000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=300000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

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

ALTER SYSTEM FLUSH SHARED_POOL;

SET AUTOTRACE OFF

EXEC :N1:=1
EXEC :N2:=2

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=10

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=100

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=1000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=10000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=100000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1
EXEC :N2:=300000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

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

SET AUTOTRACE TRACEONLY STATISTICS
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'DIFF_EXPLAIN_PLAN_TEST';

EXEC :N1:=1
EXEC :N2:=2

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=10
SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=100

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=1000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=10000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=100000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

EXEC :N1:=1
EXEC :N2:=300000

SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

SET AUTOTRACE OFF

SPOOL OFF 

There are three sections in the script:

  1. Display the AUTOTRACE generated execution plans without executing the queries, adjusting the bind variable values before each execution.
  2. Execute the SQL statement and display the actual execution plan using DBMS_XPLAN, adjusting the bind variable values before each execution (note that the flush of the shared pool seems to be required, the SQL statement is executed a couple times with each set of bind variable values to trigger adaptive cursor sharing in Oracle 11.1.0.6 and above).
  3. Execute the SQL statement displaying only the execution statistics, with a 10046 trace at level 8 enabled.

What were the results on Oracle 11.1.0.7 (you may see different results on 11.1.0.6 and 11.2.0.1)?  Section 1 of the output (slightly cleaned up) follows – keep on eye on the predicted number of rows and the Predicate Information section:

SQL> EXEC :N1:=1
SQL> EXEC :N2:=2
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=10
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=100
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=1000
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=10000
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=100000
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))        

SQL>
SQL> EXEC :N1:=1
SQL> EXEC :N2:=300000
SQL>
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------                    
Plan hash value: 2267210268   

------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              | 15000 |  7617K|       |   498   (1)| 00:00:06 |
|*  1 |  FILTER                       |              |       |       |       |            |          |
|*  2 |   HASH JOIN                   |              | 15000 |  7617K|  3992K|   498   (1)| 00:00:06 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1350 |       |       |     4   (0)| 00:00:01 |
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 15000 |  3808K|       |    55   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1350 |       |       |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))        
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))        
   6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))

Notice that the optimizer is estimating that each table will return 15,000 of the 300,000 rows, 5% of the rows in the tables.  Also notice in the Predicate Information section that AUTOTRACE is treating each of the bind variables as if it were defined as a VARCHAR2, rather than a NUMBER.

Next, we will move on to the second section of the script to see the actual execution plans.  Keep an eye on the E-Rows column, the execution plan, and the order of the query results.

SQL> EXEC :N1:=1
SQL> EXEC :N2:=2
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

        C1         C1 T T     
---------- ---------- - -     
         1          1 A A     
         2          2 A A     

SQL_ID  bgjafhqwjt1zt, child number 0
Plan hash value: 4256353061   
---------------------------------------------------------------------------------------------------------                     
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                     
---------------------------------------------------------------------------------------------------------                     
|   0 | SELECT STATEMENT               |              |      1 |        |      2 |00:00:00.01 |      11 |                     
|*  1 |  FILTER                        |              |      1 |        |      2 |00:00:00.01 |      11 |                     
|   2 |   NESTED LOOPS                 |              |      1 |        |      2 |00:00:00.01 |      11 |                     
|   3 |    NESTED LOOPS                |              |      1 |      1 |      2 |00:00:00.01 |       9 |                     
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |      2 |      2 |00:00:00.01 |       5 |                     
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |      1 |      2 |      2 |00:00:00.01 |       3 |                     
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |      2 |      1 |      2 |00:00:00.01 |       4 |                     
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |      2 |      1 |      2 |00:00:00.01 |       2 |                     
---------------------------------------------------------------------------------------------------------                     

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)     
   6 - access("T1"."C1"="T2"."C1")                   
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))   

SQL> EXEC :N1:=1
SQL> EXEC :N2:=10
SQL> SELECT
  2    T1.C1,
  3    T2.C1,
  4    SUBSTR(T1.C2,1,1) T1_C2,
  5    SUBSTR(T2.C2,1,1) T2_C2
  6  FROM
  7    T1,
  8    T2
  9  WHERE
 10    T1.C1=T2.C1
 11    AND T1.C1 BETWEEN :N1 AND :N2;

        C1         C1 T T     
---------- ---------- - -     
         1          1 A A     
         2          2 A A     
         3          3 A A     
         4          4 A A     
         5          5 A A     
         6          6 A A     
         7          7 A A     
         8          8 A A     
         9          9 A A     
        10         10 A A     

SQL_ID  bgjafhqwjt1zt, child number 0
Plan hash value: 4256353061   
---------------------------------------------------------------------------------------------------------                     
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                     
---------------------------------------------------------------------------------------------------------                     
|   0 | SELECT STATEMENT               |              |      1 |        |     10 |00:00:00.01 |      24 |                     
|*  1 |  FILTER                        |              |      1 |        |     10 |00:00:00.01 |      24 |                     
|   2 |   NESTED LOOPS                 |              |      1 |        |     10 |00:00:00.01 |      24 |                     
|   3 |    NESTED LOOPS                |              |      1 |      1 |     10 |00:00:00.01 |      14 |                     
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |      2 |     10 |00:00:00.01 |       5 |                     
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |      1 |      2 |     10 |00:00:00.01 |       3 |                     
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |     10 |      1 |     10 |00:00:00.01 |       9 |                     
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |     10 |      1 |     10 |00:00:00.01 |      10 |                     
---------------------------------------------------------------------------------------------------------                     

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)     
   6 - access("T1"."C1"="T2"."C1")                   
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))    

SQL_ID  bgjafhqwjt1zt, child number 0                
Plan hash value: 4256353061   
---------------------------------------------------------------------------------------------------------                     
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                     
---------------------------------------------------------------------------------------------------------                     
|   0 | SELECT STATEMENT               |              |      1 |        |    100 |00:00:00.01 |     117 |                     
|*  1 |  FILTER                        |              |      1 |        |    100 |00:00:00.01 |     117 |                     
|   2 |   NESTED LOOPS                 |              |      1 |        |    100 |00:00:00.01 |     117 |                     
|   3 |    NESTED LOOPS                |              |      1 |      1 |    100 |00:00:00.01 |      17 |                     
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |      2 |    100 |00:00:00.01 |       8 |                     
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |      1 |      2 |    100 |00:00:00.01 |       3 |                     
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |    100 |      1 |    100 |00:00:00.01 |       9 |                     
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |    100 |      1 |    100 |00:00:00.01 |     100 |                     
---------------------------------------------------------------------------------------------------------                     

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)     
   6 - access("T1"."C1"="T2"."C1")                   
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))    

SQL> EXEC :N1:=1
SQL> EXEC :N2:=1000

        C1         C1 T T     
---------- ---------- - -     
         1          1 A A     
         2          2 A A     
         3          3 A A     
         4          4 A A     
         5          5 A A     
...
       997        997 A A     
       998        998 A A     
       999        999 A A     
      1000       1000 A A     

SQL_ID  bgjafhqwjt1zt, child number 0                
Plan hash value: 4256353061   
---------------------------------------------------------------------------------------------------------                     
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                     
---------------------------------------------------------------------------------------------------------                     
|   0 | SELECT STATEMENT               |              |      1 |        |   1000 |00:00:00.01 |    1087 |                     
|*  1 |  FILTER                        |              |      1 |        |   1000 |00:00:00.01 |    1087 |                     
|   2 |   NESTED LOOPS                 |              |      1 |        |   1000 |00:00:00.01 |    1087 |                     
|   3 |    NESTED LOOPS                |              |      1 |      1 |   1000 |00:00:00.01 |      87 |                     
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |      2 |   1000 |00:00:00.01 |      61 |                     
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |      1 |      2 |   1000 |00:00:00.01 |      13 |                     
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |   1000 |      1 |   1000 |00:00:00.01 |      26 |                     
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |   1000 |      1 |   1000 |00:00:00.01 |    1000 |                     
---------------------------------------------------------------------------------------------------------                     

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)     
   6 - access("T1"."C1"="T2"."C1")                   
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))   

SQL> EXEC :N1:=1
SQL> EXEC :N2:=10000

        C1         C1 T T     
---------- ---------- - -     
         1          1 A A     
         2          2 A A     
         3          3 A A     
         4          4 A A     
         5          5 A A     
...
      9997       9997 A A     
      9998       9998 A A     
      9999       9999 A A     
     10000      10000 A A     

SQL_ID  bgjafhqwjt1zt, child number 1                
Plan hash value: 2267210268   
-----------------------------------------------------------------------------------------------------------------------------------                  
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |                  
-----------------------------------------------------------------------------------------------------------------------------------                  
|   0 | SELECT STATEMENT              |              |      1 |        |  10000 |00:00:00.03 |     975 |       |       |          |                  
|*  1 |  FILTER                       |              |      1 |        |  10000 |00:00:00.03 |     975 |       |       |          |                  
|*  2 |   HASH JOIN                   |              |      1 |   9999 |  10000 |00:00:00.03 |     975 |  3337K|   921K| 3324K (0)|                  
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           |      1 |  10000 |  10000 |00:00:00.01 |     390 |       |       |          |                  
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |      1 |  10000 |  10000 |00:00:00.01 |      19 |       |       |          |                  
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           |      1 |  10000 |  10000 |00:00:00.01 |     585 |       |       |          |                  
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |      1 |  10000 |  10000 |00:00:00.01 |     118 |       |       |          |                  
-----------------------------------------------------------------------------------------------------------------------------------                  

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                   
   4 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)     
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)     

SQL> EXEC :N1:=1
SQL> EXEC :N2:=100000

        C1         C1 T T     
---------- ---------- - -     
        28         28 A A     
        29         29 A A     
        30         30 A A     
        31         31 A A     
        32         32 A A     
...
     98763      98763 A A     
     98764      98764 A A     
     98765      98765 A A     
     98766      98766 A A     

SQL_ID  bgjafhqwjt1zt, child number 2                
Plan hash value: 487071653    
-----------------------------------------------------------------------------------------------------------------             
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |             
-----------------------------------------------------------------------------------------------------------------             
|   0 | SELECT STATEMENT    |      |      1 |        |    100K|00:00:00.29 |   23219 |       |       |          |             
|*  1 |  FILTER             |      |      1 |        |    100K|00:00:00.29 |   23219 |       |       |          |             
|*  2 |   HASH JOIN         |      |      1 |    100K|    100K|00:00:00.29 |   23219 |    28M|  3683K|   29M (0)|             
|*  3 |    TABLE ACCESS FULL| T1   |      1 |    100K|    100K|00:00:00.03 |   11128 |       |       |          |             
|*  4 |    TABLE ACCESS FULL| T2   |      1 |    100K|    100K|00:00:00.03 |   12091 |       |       |          |             
-----------------------------------------------------------------------------------------------------------------             

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                   
   3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))   
   4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))   

SQL> EXEC :N1:=1
SQL> EXEC :N2:=300000

        C1         C1 T T     
---------- ---------- - -     
        31         31 A A     
        34         34 A A     
        35         35 A A     
        37         37 A A     
        44         44 A A     
...
    276467     276467 A A     
    276910     276910 A A     
    277750     277750 A A     
    277771     277771 A A     

SQL_ID  bgjafhqwjt1zt, child number 3                
Plan hash value: 487071653    
---------------------------------------------------------------------------------------------------------------------------------------------        
| Id  | Operation           | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem | Used-Tmp|        
---------------------------------------------------------------------------------------------------------------------------------------------        
|   0 | SELECT STATEMENT    |      |      1 |        |    300K|00:00:06.67 |   23351 |  15996 |  15996 |       |       |          |         |        
|*  1 |  FILTER             |      |      1 |        |    300K|00:00:06.67 |   23351 |  15996 |  15996 |       |       |          |         |        
|*  2 |   HASH JOIN         |      |      1 |    300K|    300K|00:00:06.37 |   23351 |  15996 |  15996 |    85M|  7366K|   43M (1)|     132K|        
|*  3 |    TABLE ACCESS FULL| T1   |      1 |    300K|    300K|00:00:00.01 |   11128 |      0 |      0 |       |       |          |         |        
|*  4 |    TABLE ACCESS FULL| T2   |      1 |    300K|    300K|00:00:00.01 |   12223 |      0 |      0 |       |       |          |         |        
---------------------------------------------------------------------------------------------------------------------------------------------        

Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                   
   3 - filter(("T1"."C1">=:N1 AND "T1"."C1"<=:N2))   
   4 - filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))   

Next, we will move on to the third section of the script to see the output of TKPROF.  The Oracle 11.1.0.6 client home happened to be first in my path before any other Oracle home.  I renamed the trace file from the server and processed it with TKPROF:

tkprof DIFF_EXPLAIN_PLAN_TEST.trc DIFF_EXPLAIN_PLAN_TEST_TRC.txt

What was in the DIFF_EXPLAIN_PLAN_TEST_TRC.txt file generated by TKPROF?

********************************************************************************
SELECT
  T1.C1,
  T2.C1,
  SUBSTR(T1.C2,1,1) T1_C2,
  SUBSTR(T2.C2,1,1) T2_C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.00       0.00          0          0          0           0
Execute      7      0.01       0.03          0          0          0           0
Fetch     4120      3.52      10.91      18216      47844          0      411112
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4134      3.54      10.95      18216      47844          0      411112

Misses in library cache during parse: 0
Misses in library cache during execute: 4
Optimizer mode: ALL_ROWS
Parsing user id: 518 

Rows     Row Source Operation
-------  ---------------------------------------------------
      2  FILTER  (cr=11 pr=0 pw=0 time=0 us)
      2   NESTED LOOPS  (cr=11 pr=0 pw=0 time=0 us)
      2    NESTED LOOPS  (cr=9 pr=0 pw=0 time=0 us cost=5 size=520 card=1)
      2     TABLE ACCESS BY INDEX ROWID T1 (cr=5 pr=0 pw=0 time=0 us cost=3 size=520 card=2)
      2      INDEX RANGE SCAN SYS_C0030337 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=2)(object id 87187)
      2     INDEX UNIQUE SCAN SYS_C0030338 (cr=4 pr=0 pw=0 time=0 us cost=0 size=0 card=1)(object id 87189)
      2    TABLE ACCESS BY INDEX ROWID T2 (cr=2 pr=0 pw=0 time=0 us cost=1 size=260 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    4120        0.00          0.02
  SQL*Net message from client                  4120        0.01          3.21
  direct path write temp                       1128        0.99          2.06
  direct path read temp                        1128        0.17          5.10
********************************************************************************

Interesting, all seven executions with different bind variable values used the same execution plan.  That means that this command lied?:

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

Wait a minute, that is not in the title of this article.  If only I knew how to read a raw 10046 extended SQL trace, I could read this:

STAT #8 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=11 pr=0 pw=0 time=0 us)'
STAT #8 id=2 cnt=2 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=11 pr=0 pw=0 time=0 us)'
STAT #8 id=3 cnt=2 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=9 pr=0 pw=0 time=0 us cost=5 size=520 card=1)'
STAT #8 id=4 cnt=2 pid=3 pos=1 obj=87264 op='TABLE ACCESS BY INDEX ROWID T1 (cr=5 pr=0 pw=0 time=0 us cost=3 size=520 card=2)'
STAT #8 id=5 cnt=2 pid=4 pos=1 obj=87265 op='INDEX RANGE SCAN SYS_C0030339 (cr=3 pr=0 pw=0 time=0 us cost=2 size=0 card=2)'
STAT #8 id=6 cnt=2 pid=3 pos=2 obj=87267 op='INDEX UNIQUE SCAN SYS_C0030340 (cr=4 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'
STAT #8 id=7 cnt=2 pid=2 pos=2 obj=87266 op='TABLE ACCESS BY INDEX ROWID T2 (cr=2 pr=0 pw=0 time=0 us cost=1 size=260 card=1)'
...
STAT #5 id=1 cnt=300000 pid=0 pos=1 obj=0 op='FILTER  (cr=23515 pr=15705 pw=15705 time=4741368 us)'
STAT #5 id=2 cnt=300000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=23515 pr=15705 pw=15705 time=4741368 us cost=13774 size=156000000 card=300000)'
STAT #5 id=3 cnt=300000 pid=2 pos=1 obj=87264 op='TABLE ACCESS FULL T1 (cr=11128 pr=0 pw=0 time=31126 us cost=3024 size=78000000 card=300000)'
STAT #5 id=4 cnt=300000 pid=2 pos=2 obj=87266 op='TABLE ACCESS FULL T2 (cr=12387 pr=0 pw=0 time=155851 us cost=3024 size=78000000 card=300000)'

If you do know how to read the STAT lines in a 10046 extended SQL trace, you would know that the execution plan definitely did change between the first and last execution when 10046 extended SQL tracing was enabled.

We might be inclined to do some checking, like this:

SELECT
  CHILD_NUMBER,
  EXECUTIONS,
  ROWS_PROCESSED,
  BUFFER_GETS,
  BIND_SET_HASH_VALUE
FROM
  V$SQL_CS_STATISTICS
WHERE
  SQL_ID='bgjafhqwjt1zt'
ORDER BY
  CHILD_NUMBER;

CHILD_NUMBER EXECUTIONS ROWS_PROCESSED BUFFER_GETS BIND_SET_HASH_VALUE
------------ ---------- -------------- ----------- -------------------
           0          1          12001        1087           722894381
           0          1             25         124          2702357211
           1          1         180000         975           982654583
           2          1        1000000       23219          2772294946
           3          1        3000000       23351          1545127490
           4          1             25          11          2702357211
           5          1            140           8             6258482
           6          1           1400          14          4281096765
           7          1          18000         102           722894381

Or, we might try doing something like this:

SPOOL 'DIFF_EXPLAIN_PLANS_ADAPT.TXT'

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('bgjafhqwjt1zt',NULL,'TYPICAL'));

SPOOL OFF

PLAN_TABLE_OUTPUT      
------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  bgjafhqwjt1zt, child number 0                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 4256353061       
-----------------------------------------------------------------------------------------------        
| Id  | Operation                      | Name         | Rows  | Bytes | Cost (%CPU)| Time     |        
-----------------------------------------------------------------------------------------------        
|   0 | SELECT STATEMENT               |              |       |       |     5 (100)|          |        
|*  1 |  FILTER                        |              |       |       |            |          |        
|   2 |   NESTED LOOPS                 |              |       |       |            |          |        
|   3 |    NESTED LOOPS                |              |     1 |   520 |     5   (0)| 00:00:01 |        
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |     2 |   520 |     3   (0)| 00:00:01 |        
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |     2 |       |     2   (0)| 00:00:01 |        
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |     1 |       |     0   (0)|          |        
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |     1 |   260 |     1   (0)| 00:00:01 |        
-----------------------------------------------------------------------------------------------        

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T1"."C1"="T2"."C1")                       
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))       

SQL_ID  bgjafhqwjt1zt, child number 1                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 2267210268       
------------------------------------------------------------------------------------------------------ 
| Id  | Operation                     | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | 
------------------------------------------------------------------------------------------------------ 
|   0 | SELECT STATEMENT              |              |       |       |       |  1042 (100)|          | 
|*  1 |  FILTER                       |              |       |       |       |            |          | 
|*  2 |   HASH JOIN                   |              |  9999 |  5077K|  2664K|  1042   (1)| 00:00:13 | 
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           | 10000 |  2539K|       |   391   (0)| 00:00:05 | 
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 | 10000 |       |       |    20   (0)| 00:00:01 | 
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           | 10000 |  2539K|       |   391   (0)| 00:00:05 | 
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 | 10000 |       |       |    20   (0)| 00:00:01 | 
------------------------------------------------------------------------------------------------------ 

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   4 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)         

SQL_ID  bgjafhqwjt1zt, child number 2                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 487071653        
------------------------------------------------------------------------------------                   
| Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |                   
------------------------------------------------------------------------------------                   
|   0 | SELECT STATEMENT    |      |       |       |       |  8623 (100)|          |                   
|*  1 |  FILTER             |      |       |       |       |            |          |                   
|*  2 |   HASH JOIN         |      |   100K|    49M|    25M|  8623   (1)| 00:01:44 |                   
|*  3 |    TABLE ACCESS FULL| T1   |   100K|    24M|       |  3023   (1)| 00:00:37 |                   
|*  4 |    TABLE ACCESS FULL| T2   |   100K|    24M|       |  3023   (1)| 00:00:37 |                   
------------------------------------------------------------------------------------                   

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))       
   4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))       

SQL_ID  bgjafhqwjt1zt, child number 3                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 487071653        
------------------------------------------------------------------------------------                   
| Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |                   
------------------------------------------------------------------------------------                   
|   0 | SELECT STATEMENT    |      |       |       |       | 13774 (100)|          |                   
|*  1 |  FILTER             |      |       |       |       |            |          |                   
|*  2 |   HASH JOIN         |      |   300K|   148M|    77M| 13774   (1)| 00:02:46 |                   
|*  3 |    TABLE ACCESS FULL| T1   |   300K|    74M|       |  3024   (1)| 00:00:37 |                   
|*  4 |    TABLE ACCESS FULL| T2   |   300K|    74M|       |  3024   (1)| 00:00:37 |                   
------------------------------------------------------------------------------------                   

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   3 - filter(("T1"."C1">=:N1 AND "T1"."C1"<=:N2))       
   4 - filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))       

SQL_ID  bgjafhqwjt1zt, child number 4                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 4256353061       
-----------------------------------------------------------------------------------------------        
| Id  | Operation                      | Name         | Rows  | Bytes | Cost (%CPU)| Time     |        
-----------------------------------------------------------------------------------------------        
|   0 | SELECT STATEMENT               |              |       |       |     5 (100)|          |        
|*  1 |  FILTER                        |              |       |       |            |          |        
|   2 |   NESTED LOOPS                 |              |       |       |            |          |        
|   3 |    NESTED LOOPS                |              |     1 |   520 |     5   (0)| 00:00:01 |        
|   4 |     TABLE ACCESS BY INDEX ROWID| T1           |     2 |   520 |     3   (0)| 00:00:01 |        
|*  5 |      INDEX RANGE SCAN          | SYS_C0030339 |     2 |       |     2   (0)| 00:00:01 |        
|*  6 |     INDEX UNIQUE SCAN          | SYS_C0030340 |     1 |       |     0   (0)|          |        
|   7 |    TABLE ACCESS BY INDEX ROWID | T2           |     1 |   260 |     1   (0)| 00:00:01 |        
-----------------------------------------------------------------------------------------------        

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T1"."C1"="T2"."C1")                       
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))       

SQL_ID  bgjafhqwjt1zt, child number 5                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 2267210268       
----------------------------------------------------------------------------------------------         
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |         
----------------------------------------------------------------------------------------------         
|   0 | SELECT STATEMENT              |              |       |       |     7 (100)|          |         
|*  1 |  FILTER                       |              |       |       |            |          |         
|*  2 |   HASH JOIN                   |              |     9 |  4680 |     7  (15)| 00:00:01 |         
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           |    10 |  2600 |     3   (0)| 00:00:01 |         
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |    10 |       |     2   (0)| 00:00:01 |         
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           |    10 |  2600 |     3   (0)| 00:00:01 |         
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |    10 |       |     2   (0)| 00:00:01 |         
----------------------------------------------------------------------------------------------         

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   4 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)         

SQL_ID  bgjafhqwjt1zt, child number 6                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 2267210268       
----------------------------------------------------------------------------------------------         
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |         
----------------------------------------------------------------------------------------------         
|   0 | SELECT STATEMENT              |              |       |       |    13 (100)|          |         
|*  1 |  FILTER                       |              |       |       |            |          |         
|*  2 |   HASH JOIN                   |              |    99 | 51480 |    13   (8)| 00:00:01 |         
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           |   100 | 26000 |     6   (0)| 00:00:01 |         
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |   100 |       |     2   (0)| 00:00:01 |         
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           |   100 | 26000 |     6   (0)| 00:00:01 |         
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |   100 |       |     2   (0)| 00:00:01 |         
----------------------------------------------------------------------------------------------         

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   4 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)         

SQL_ID  bgjafhqwjt1zt, child number 7                    
-------------------------------------                    
SELECT   T1.C1,   T2.C1,   SUBSTR(T1.C2,1,1) T1_C2,   SUBSTR(T2.C2,1,1)         
T2_C2 FROM   T1,   T2 WHERE   T1.C1=T2.C1   AND T1.C1 BETWEEN :N1 AND           
:N2                    

Plan hash value: 2267210268       
----------------------------------------------------------------------------------------------         
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |         
----------------------------------------------------------------------------------------------         
|   0 | SELECT STATEMENT              |              |       |       |    83 (100)|          |         
|*  1 |  FILTER                       |              |       |       |            |          |         
|*  2 |   HASH JOIN                   |              |   999 |   507K|    83   (2)| 00:00:01 |         
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           |  1000 |   253K|    41   (0)| 00:00:01 |         
|*  4 |     INDEX RANGE SCAN          | SYS_C0030339 |  1000 |       |     3   (0)| 00:00:01 |         
|   5 |    TABLE ACCESS BY INDEX ROWID| T2           |  1000 |   253K|    41   (0)| 00:00:01 |         
|*  6 |     INDEX RANGE SCAN          | SYS_C0030340 |  1000 |       |     3   (0)| 00:00:01 |         
----------------------------------------------------------------------------------------------         

Predicate Information (identified by operation id):      
---------------------------------------------------      
   1 - filter(:N1<=:N2)
   2 - access("T1"."C1"="T2"."C1")                       
   4 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)         

You might be wondering if TKPROF in 11.1.0.7 or 11.2.0.1 lie about the execution plan captured in an extended 10046 SQL trace.  I would tell you, but this blog article is now too long. 🙂

« »


Actions

Information

3 responses

11 01 2010
Narendra (05:17:38) :

Charles,

You definitely know how to write attention-grabing titles for your blog posts.
Could the same execution plan reported by TkProf be due to default “aggregate=yes” option used by TkProf command ?

p.s. Don’t worry. I got the message from your comment on last post. 🙂
I will try and see for myself.

Reply
12 02 2010
Blogroll Report 08/01/2009 – 15/01/2010 « Coskan’s Approach to Oracle (14:00:05) :

[…] 10-How does execution plan gathering can be wrong? Charles Hooper-Explain Plan Lies, Autotrace Lies, TKPROF Lies, What is the Plan? […]

Reply
6 03 2013
Understanding Oracle traces and plan | oraclebits (11:52:22) :

[…] https://hoopercharles.wordpress.com/2010/01/30/execution-plans-what-is-the-plan-and-where-do-i-find-it/ (3 part series)https://hoopercharles.wordpress.com/2009/12/01/10046-extended-sql-trace-interpretation/ (2 part series)https://hoopercharles.wordpress.com/2010/01/11/explain-plan-lies-autotrace-lies-tkprof-lies-what-is-t… […]

Reply

Leave a reply to Understanding Oracle traces and plan | oraclebits Cancel reply