SQL PLAN_HASH_VALUE Changes for the Same SQL Statement

December 1, 2009

In this OTN thread:
http://forums.oracle.com/forums/thread.jspa?messageID=3697025

A user asked the following question:

How would you explain the following

select snap_id,sql_id,plan_hash_value from
 dba_hist_sqlstat where sql_id='cmrh5mk9854vs'

SNAP_ID SQL_ID        PLAN_HASH_VALUE
13487   cmrh5mk9854vs 3314988613
14471   cmrh5mk9854vs 3452699090

 Two different hash values for the same same sqls

I believe that your real question is why does that happen?  There are several reasons for the change in plan, here is a demonstration on Oracle 10.2.0.2:

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

INSERT INTO T1
SELECT
  TO_CHAR(ROWNUM),
  LPAD(CHR(65 + ROUND(ROWNUM/1000)),255,CHR(65 + ROUND(ROWNUM/1000)))
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

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

The table created by the above contains 1,000,000 rows with an index on column C1. Column C1 is defined as a VARCHAR2, but I placed numbers into the column. Now for the first part of the test, where I request that Oracle display the execution plan for a SQL statement without actually executing the SQL statement:

SET AUTOTRACE TRACEONLY EXPLAIN

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER

SELECT
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------
Plan hash value: 3390613643
---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |  2500 |   639K|  1001   (1)| 00:00:05 |
|*  1 |  FILTER                      |              |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   639K|  1001   (1)| 00:00:05 |
|*  3 |    INDEX RANGE SCAN          | SYS_C0020503 |  4500 |       |    20   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

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

VARIABLE N1 VARCHAR2(20)
VARIABLE N2 VARCHAR2(20)

EXEC :N1 := '1'
EXEC :N2 := '9999'

SELECT
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN :N1 AND :N2;

Execution Plan
----------------------------------------------------------
Plan hash value: 3390613643

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |  2500 |   639K|  1001   (1)| 00:00:05 |
|*  1 |  FILTER                      |              |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   639K|  1001   (1)| 00:00:05 |
|*  3 |    INDEX RANGE SCAN          | SYS_C0020503 |  4500 |       |    20   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

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

The first execution plan displayed is incorrect. I have a utility (my Toy Project for Performance Tuning) which retrieves all plans for a SQL_ID using DBMS_XPLAN and also checks V$SQL_SHARED_CURSOR and V$SQL_BIND_METADATA. This is the output:

SQL_ID  cguuvrry2hx1z, child number 0
-------------------------------------
SELECT   C1,   C2 FROM   T1 WHERE   C1 BETWEEN :N1 AND :N2

Plan hash value: 3332582666

------------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |  1970 (100)|          |        |
|*  1 |  FILTER            |      |       |       |            |          |        |
|*  2 |   TABLE ACCESS FULL| T1   |  2500 |   639K|  1970   (5)| 00:00:10 |    CHK |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   2 - filter((TO_NUMBER("C1")>=:N1 AND TO_NUMBER("C1")<=:N2))

Bind Descriptions:
  Pos  MLen  Data Type   Bind Name
    1    22  NUMBER      N1
    2    22  NUMBER      N2

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
BIND_MISMATCH - The bind metadata does not match the existing child cursor.

SQL_ID  cguuvrry2hx1z, child number 1
-------------------------------------
SELECT   C1,   C2 FROM   T1 WHERE   C1 BETWEEN :N1 AND :N2

Plan hash value: 3390613643

------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |       |       |  1001 (100)|          |        |
|*  1 |  FILTER                      |              |       |       |            |          |        |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   639K|  1001   (1)| 00:00:05 |    CHK |
|*  3 |    INDEX RANGE SCAN          | SYS_C0020503 |  4500 |       |    20   (0)| 00:00:01 |    CHK |
------------------------------------------------------------------------------------------------------

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

Bind Descriptions:
  Pos  MLen  Data Type   Bind Name
    1    32  VARCHAR2    N1
    2    32  VARCHAR2    N2

Notice the Predicate Information and Bind Descriptions for the first execution plan. Child #1 was created due to “The bind metadata does not match the existing child cursor”. Now another test:

ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=1000;

SELECT
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN :N1 AND :N2;

Statistics
--------------------------------------------------------------------------------
1 recursive calls
0 db block gets
102765 consistent gets
36619 physical reads
0 redo size
22387973 bytes sent via SQL*Net to client
733583 bytes received via SQL*Net from client
66661 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
999890 rows processed

This is the output from my utility program which shows another child cursor:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
OPTIMIZER_MISMATCH - The optimizer environment does not match the existing child cursor.

SQL_ID  cguuvrry2hx1z, child number 2
-------------------------------------
SELECT   C1,   C2 FROM   T1 WHERE   C1 BETWEEN :N1 AND :N2

Plan hash value: 3332582666

------------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |  1964 (100)|          |        |
|*  1 |  FILTER            |      |       |       |            |          |        |
|*  2 |   TABLE ACCESS FULL| T1   |   999K|   249M|  1964   (5)| 00:00:10 |    CHK |
------------------------------------------------------------------------------------

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

   1 - filter(:N1<=:N2)
   2 - filter(("C1"<=:N2 AND "C1">=:N1))

Bind Descriptions:
  Pos  MLen  Data Type   Bind Name
    1    32  VARCHAR2    N1
    2    32  VARCHAR2    N2

Notice the reason for child #2 being created “The optimizer environment does not match the existing child cursor”.

I then disconnected from the database instance and reconnected to reset the OPTIMIZER_INDEX_COST_ADJ parameter to the system default. One more test, gather statistics forcing current plans to be invalidated (there is usually a delay when statistics are gathered before plans accessing those objects are invalidated):

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

SET AUTOTRACE TRACEONLY STATISTICS

VARIABLE N1 VARCHAR2(20)
VARIABLE N2 VARCHAR2(20)

EXEC :N1 := '1'
EXEC :N2 := '9999'

SELECT
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN :N1 AND :N2;

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
     102765  consistent gets
      35424  physical reads
          0  redo size
   22387973  bytes sent via SQL*Net to client
     733583  bytes received via SQL*Net from client
      66661  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     999890  rows processed

My utility program now shows that there is a single plan, which was affected by bind peeking.

SQL_ID  cguuvrry2hx1z, child number 0
-------------------------------------
SELECT   C1,   C2 FROM   T1 WHERE   C1 BETWEEN :N1 AND :N2

Plan hash value: 3332582666

------------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |  1964 (100)|          |        |
|*  1 |  FILTER            |      |       |       |            |          |        |
|*  2 |   TABLE ACCESS FULL| T1   |   999K|   249M|  1964   (5)| 00:00:10 |    CHK |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   2 - filter(("C1"<=:N2 AND "C1">=:N1))

Bind Descriptions:
  Pos  MLen  Data Type   Bind Name
    1    32  VARCHAR2    N1
    2    32  VARCHAR2    N2

• I had originally planned to mention the Oracle 11g introduced adaptive cursor sharing, which is another source of different plans for the same SQL statement. So, in summary some of the sources of the plan changing:
  * Parsing a SQL statement with the bind variable values not defined
  * Parsing a SQL statement with the bind variables defined as the wrong type (or specified as a different type)
  * Statistics collection forcing the invalidation of cursors, which forces a new hard parse on the next execution (on 10g and above, statistics collection does not cause an immediate invalidation of cursors accessing objects for which statistics were collected)
  * Changes in the statistics, or even lack of change in the statistics with supplied values in the SQL statement appearing to be increasingly above or below the maximum and minimum values for the columns.
  * Bind peeking, where different bind variable values were specified on each hard parse
  * Different optimizer environment for the session executing the SQL statement
  * Adaptive cursor sharing in 11g

SQL PLAN_HASH_VALUE Change When Literals Change?

In this OTN thread:
http://forums.oracle.com/forums/thread.jspa?messageID=3697025

A user asked the following question:

Is there any way to identify the sqls with same execution plan, for us the problem is, sql is submitted with parameter hardcoded in where clause, which changes the sqlid and plan hash value, as the plan hash value changes but the infact plan remains same, i want to identify such sqlid?

The PLAN_HASH_VALUE should remain the same if the plan is the same, even if hardcoded values are specified in the WHERE clause. For example, a table T1 with an ID column and a DESCRIPTION column with an index on the ID column – first, four SQL statements are executed with different values specified for ID in the WHERE clause:

SELECT /*+ TEST FIND ME */ 1 FROM T1 WHERE ID=1;
SELECT /*+ TEST FIND ME */ 2 FROM T1 WHERE ID=2;
SELECT /*+ TEST FIND ME */ 3 FROM T1 WHERE ID=3;
SELECT /*+ TEST FIND ME */ 4 FROM T1 WHERE ID=4;

 Now we search the V$SQL view for the SQL_IDs and PLAN_HASH_VALUEs:

SELECT
  SQL_ID,
  CHILD_NUMBER,
  PLAN_HASH_VALUE
FROM
  V$SQL
WHERE
  SQL_TEXT LIKE '% TEST FIND ME %';
 
SQL_ID        CHILD_NUMBER PLAN_HASH_VALUE
------------- ------------ ---------------
fbvgxdbddnush            0      1882569892
5f0415sr6d7qb            0      1882569892
0fpndy65tykxv            0      1882569892
5jvj4jyzyb9jt            0      1882569892
0kjp2dk2vbpra            0       903671040
 
SELECT
  SQL_TEXT
FROM
  V$SQL
WHERE
  SQL_ID='0kjp2dk2vbpra';
 
SQL_TEXT
--------------------------------------------------------------------------------
SELECT   SQL_ID,   CHILD_NUMBER,   PLAN_HASH_VALUE FROM   V$SQL WHERE   SQL_TEXT
 LIKE '% TEST FIND ME %'

The only SQL statement with a different plan hash value is the SQL statement which performed the query on V$SQL. Next, we retrieve the plans for the SQL statements:

SET LINESIZE 150
SET PAGESIZE 2000
SPOOL TEST_MY_PLANS.TXT
 
SELECT /*+ LEADING(S) */
  T.PLAN_TABLE_OUTPUT
FROM
  (SELECT
    SQL_ID,
    CHILD_NUMBER
  FROM
    V$SQL
  WHERE
    SQL_TEXT LIKE '% TEST FIND ME %') S,
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(S.SQL_ID,S.CHILD_NUMBER,'TYPICAL')) T;
 
SPOOL OFF

The spool file included the following:

SQL_ID  fbvgxdbddnush, child number 0
-------------------------------------
SELECT /*+ TEST FIND ME */ 3 FROM T1 WHERE ID=3
 
Plan hash value: 1882569892
 
---------------------------------------------------------------------------
| Id  | Operation        | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT |        |       |       |    24 (100)|          |
|*  1 |  INDEX RANGE SCAN| IND_T1 | 10000 | 40000 |    24   (0)| 00:00:01 |
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("ID"=3)
 
 
SQL_ID  5f0415sr6d7qb, child number 0
-------------------------------------
SELECT /*+ TEST FIND ME */ 2 FROM T1 WHERE ID=2
 
Plan hash value: 1882569892
 
---------------------------------------------------------------------------
| Id  | Operation        | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT |        |       |       |    24 (100)|          |
|*  1 |  INDEX RANGE SCAN| IND_T1 | 10000 | 40000 |    24   (0)| 00:00:01 |
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("ID"=2)
 
 
SQL_ID  0fpndy65tykxv, child number 0
-------------------------------------
SELECT /*+ TEST FIND ME */ 4 FROM T1 WHERE ID=4
 
Plan hash value: 1882569892
 
---------------------------------------------------------------------------
| Id  | Operation        | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT |        |       |       |    24 (100)|          |
|*  1 |  INDEX RANGE SCAN| IND_T1 | 10000 | 40000 |    24   (0)| 00:00:01 |
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("ID"=4)
 
 
SQL_ID  5jvj4jyzyb9jt, child number 0
-------------------------------------
SELECT /*+ TEST FIND ME */ 1 FROM T1 WHERE ID=1
 
Plan hash value: 1882569892
 
---------------------------------------------------------------------------
| Id  | Operation        | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT |        |       |       |    24 (100)|          |
|*  1 |  INDEX RANGE SCAN| IND_T1 | 10000 | 40000 |    24   (0)| 00:00:01 |
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("ID"=1)
 
 
SQL_ID  0kjp2dk2vbpra, child number 0
-------------------------------------
SELECT   SQL_ID,   CHILD_NUMBER,   PLAN_HASH_VALUE FROM   V$SQL WHERE
SQL_TEXT LIKE '% TEST FIND ME %'
 
Plan hash value: 903671040
 
---------------------------------------------------------------------------
| Id  | Operation        | Name              | Rows  | Bytes | Cost (%CPU)|
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                   |       |       |     1 (100)|
|*  1 |  FIXED TABLE FULL| X$KGLCURSOR_CHILD |     1 |   549 |     0   (0)|
---------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("KGLNAOBJ" LIKE '% TEST FIND ME %' AND
              "INST_ID"=USERENV('INSTANCE')))

So, the answer is that the SQL PLAN_HASH_VALUE does not change when literals in the WHERE clause change, if the actual execution plan is the same.

SQL Date Ranges with Connect By

A question appeared in one of the OTN forums:
http://forums.oracle.com/forums/thread.jspa?messageID=3891491

—

USER_NAME    FROM_DATE  TO_DATE    COMMENTS
--------------------------------------------------------------------------------
Uma Shankar   2-Nov-09   5-Nov-09  Comment1
Veera        11-Nov-09  13-Nov-09  Comment2
Uma Shankar  15-Dec-09  17-Dec-09  Commnet3
Vinod        20-Oct-09  21-Oct-09  Comments4

The above table is the user leave calendar.  Now I need to display the users who are on leave between 01-Nov-2009 to 30-Nov-2009.  The output should look like:

USER_NAME   FROM_DATE COMMENTS
--------------------------------------------------------------------------------
Uma Shankar  2-Nov-09 Comment1
Uma Shankar  3-Nov-09 Comment1
Uma Shankar  4-Nov-09 Comment1
Uma Shankar  5-Nov-09 Comment1
Veera       11-Nov-09 Comment2
Veera       12-Nov-09 Comment2
Veera       13-Nov-09 Comment2

—

How would one go about finding a solution for the above problem?  Possibly by breaking the problem into smaller steps.

Here is a test set up:

CREATE TABLE T1(
  USERNAME VARCHAR2(30),
  FROM_DATE DATE,
  TO_DATE DATE,
  COMMENTS VARCHAR2(100));

INSERT INTO T1 VALUES ('Uma Shankar', '02-Nov-09','05-Nov-09','Comment1');
INSERT INTO T1 VALUES ('Veera','11-Nov-09','13-Nov-09','Comment2');
INSERT INTO T1 VALUES ('Uma Shankar','15-Dec-09','17-Dec-09','Commnet3');
INSERT INTO T1 VALUES ('Vinod','20-Oct-09','21-Oct-09','Comments4');
INSERT INTO T1 VALUES ('Mo','20-Oct-09','05-NOV-09','Comments4');

COMMIT;

Note that I included one additional row, where the person starts their vacation in the previous month and ends in the month of November.  You could approach the problem like this:
Assume that you would like to list all of the days of a particular month:

SELECT
  TO_DATE('01-NOV-2009','DD-MON-YYYY')+(ROWNUM-1) MONTH_DAY
FROM
  DUAL
CONNECT BY
  LEVEL<=ADD_MONTHS(TO_DATE('01-NOV-2009','DD-MON-YYYY'),1)
           -TO_DATE('01-NOV-2009','DD-MON-YYYY');

Note that the above attempts to calculate the number of days in the month of November – if it is known that the month has a particular number of days, 30 for instance, you could rewrite the CONNECT BY clause like this:

CONNECT BY
  LEVEL<=30

 Now, we need to pick up those rows of interest from the table:

SELECT
  *
FROM
  T1 T
WHERE
  (T.FROM_DATE BETWEEN TO_DATE('01-NOV-2009','DD-MON-YYYY') AND TO_DATE('30-NOV-2009','DD-MON-YYYY')
    OR T.TO_DATE BETWEEN TO_DATE('01-NOV-2009','DD-MON-YYYY') AND TO_DATE('30-NOV-2009','DD-MON-YYYY'));

USERNAME        FROM_DATE TO_DATE   COMMENTS
--------------- --------- --------- ----------
Uma Shankar     02-NOV-09 05-NOV-09 Comment1
Veera           11-NOV-09 13-NOV-09 Comment2
Mo              20-OCT-09 05-NOV-09 Comments4

If we then join the two resultsets, we have the following query:

SELECT
  *
FROM
  T1 T,
  (SELECT
    TO_DATE('01-NOV-2009','DD-MON-YYYY')+(ROWNUM-1) MONTH_DAY
  FROM
    DUAL
  CONNECT BY
    LEVEL<=ADD_MONTHS(TO_DATE('01-NOV-2009','DD-MON-YYYY'),1)-TO_DATE('01-NOV-2009','DD-MON-YYYY')) V
WHERE
  (T.FROM_DATE BETWEEN TO_DATE('01-NOV-2009','DD-MON-YYYY') AND TO_DATE('30-NOV-2009','DD-MON-YYYY')
    OR T.TO_DATE BETWEEN TO_DATE('01-NOV-2009','DD-MON-YYYY') AND TO_DATE('30-NOV-2009','DD-MON-YYYY'))
  AND V.MONTH_DAY BETWEEN T.FROM_DATE AND T.TO_DATE
ORDER BY
  USERNAME,
  MONTH_DAY;

USERNAME        FROM_DATE TO_DATE   COMMENTS   MONTH_DAY
--------------- --------- --------- ---------- ---------
Mo              20-OCT-09 05-NOV-09 Comments4  01-NOV-09
Mo              20-OCT-09 05-NOV-09 Comments4  02-NOV-09
Mo              20-OCT-09 05-NOV-09 Comments4  03-NOV-09
Mo              20-OCT-09 05-NOV-09 Comments4  04-NOV-09
Mo              20-OCT-09 05-NOV-09 Comments4  05-NOV-09
Uma Shankar     02-NOV-09 05-NOV-09 Comment1   02-NOV-09
Uma Shankar     02-NOV-09 05-NOV-09 Comment1   03-NOV-09
Uma Shankar     02-NOV-09 05-NOV-09 Comment1   04-NOV-09
Uma Shankar     02-NOV-09 05-NOV-09 Comment1   05-NOV-09
Veera           11-NOV-09 13-NOV-09 Comment2   11-NOV-09
Veera           11-NOV-09 13-NOV-09 Comment2   12-NOV-09
Veera           11-NOV-09 13-NOV-09 Comment2   13-NOV-09

What Happens when 1=2 is Included in a WHERE Clause?

The following appeared in a Usenet post:

Surprisingly, the optimizer sometimes seems to do a bad job about such constant clauses. As in “where 1 = 2” resulting in a full table scan…

The above statement is actually correct (OK, partially).  However, it might be a good idea to check the DBMS_XPLAN output and/or the output of a 10046 trace and/or the output of SET AUTOTRACE TRACEONLY STATISTICS.  For example, here is a test on Oracle 11.1.0.7 with a 100,000,000 row table with a primary key column in a freshly bounced database:

SET AUTOTRACE TRACEONLY EXPLAIN
SELECT 
  * 
FROM 
  T1 
WHERE 
  1=2;

Execution Plan 
---------------------------------------------------------- 
Plan hash value: 3332582666 
 
--------------------------------------------------------------------------- 
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     | 
--------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT   |      |     1 |    53 |       0 (0)|          | 
|*  1 |  FILTER            |      |       |       |            |          | 
|   2 |   TABLE ACCESS FULL| T1   |   100M|  5054M|   221K  (1)| 00:44:14 | 
--------------------------------------------------------------------------- 
 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
   1 - filter(NULL IS NOT NULL)

The plan indicates a full table scan, and the filter predicate indicates?
Continuing:

SET AUTOTRACE TRACEONLY STATISTICS 
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'My_Trace'; 
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8'; 
 
SELECT 
  * 
FROM 
  T1 
WHERE 
  1=2; 
 
Statistics 
---------------------------------------------------------- 
   1  recursive calls 
   0  db block gets 
   0  consistent gets 
   0  physical reads 
   0  redo size 
 301  bytes sent via SQL*Net to client 
 349  bytes received via SQL*Net from client 
   1  SQL*Net roundtrips to/from client 
   0  sorts (memory) 
   0  sorts (disk) 
   0  rows processed 
 
 
SELECT SYSDATE FROM DUAL;

A full table scan on a 100,000,000 row table which performed 0 consistent gets, interesting….

Now, a check of the 10046 extended SQL trace file:

===================== 
PARSING IN CURSOR #7 len=32 dep=0 uid=56 oct=3 lid=56 tim=327318181 hv=2373026659 ad='2775adb30' sqlid='077d50q6r30v3' 
SELECT 
  * 
FROM 
  T1 
WHERE 
  1=2 
END OF STMT 
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3332582666,tim=327318181 
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3332582666,tim=327318181 
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=527 tim=327322648 
FETCH #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3332582666,tim=327318181 
STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='FILTER  (cr=0 pr=0 pw=0 time=0 us)' 
STAT #7 id=2 cnt=0 pid=1 pos=1 obj=68961 op='TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us cost=221088 size=5300000000 card=100000000)' 
WAIT #7: nam='SQL*Net message from client' ela= 11075 driver id=1413697536 #bytes=1 p3=0 obj#=527 tim=327343489

The STAT lines in the 10046 trace also confirm that Oracle did not even bother to execute the full table scan.
Just for confirmation that rows do exist in the table:

SELECT 
  COUNT(*) 
FROM 
  T1; 
 
Statistics 
---------------------------------------------------------- 
     1  recursive calls 
     0  db block gets 
813324  consistent gets 
813317  physical reads 
     0  redo size 
   342  bytes sent via SQL*Net to client 
   360  bytes received via SQL*Net from client 
     2  SQL*Net roundtrips to/from client 
     0  sorts (memory) 
     0  sorts (disk) 
     1  rows processed 

10046 Extended SQL Trace Interpretation

December 1, 2009

(Forward to the Next Post in the Series)

10046 extended SQL trace files provide a significant level of detail specific to a single session.  Extended SQL traces are enabled by setting event 10046 to level 4 (bind variables), level 8 (wait events), or level 12 (bind variables and wait events).  There are several methods that may be used to set event 10046, partially dependent on the Oracle release version, and whether or not the event may be set interactively within the session:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');
-or-
  EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(SID,SERIAL#,WAITS=>TRUE,BINDS=>FALSE);
-or-
  EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#,WAITS=>TRUE,BINDS=>TRUE)
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);

The SID and SERIAL# may be retrieved from V$SESSION for the session of interest.  The SYS.DBMS_SYSTEM.SET_EV method is unsupported, but it works fine on older versions of Oracle where the other methods do not exist.  Not all of the above methods work in older Oracle releases.  Oracle will create the trace files in the server’s udump directory (or the trace directory with release 11.1.0.6 and later).  A logon trigger may be used to enable a 10046 extended SQL trace, possibly enabling a trace for all sessions that start the same program, or for a specific user.  10046 traces may also be enabled with the SQL*Plus ORADEBUG functionality.

Before executing any of the above commands (especially if enabled using an ALTER SYSTEM method), determine how to disable a 10046 trace, depending on how it was started:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');
-or-
  EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(SID,SERIAL#);
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,FALSE);

A short summary of several keywords found in a 10046 extended SQL trace file:
len= the number of characters in the SQL statement
dep= tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
tim= is a time stamp measured in 1/1,000,000 of a second that may be used for tracking the progress in the 10046 trace file – take the delta value of the most recent tim=, subtract the first tim=, divide the result by 1,000,000 – equals the number of seconds into the trace file.
c= CPU seconds – amount of CPU resources required at that point in the execution. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
e= Elapsed seconds – number of seconds as measured by a high precision clock at that point in the execution. This may be significantly different from CPU seconds. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
p= Physical blocks read from disk.
cr= Consistent reads
cu= Consistent reads in current mode
mis= Number of shared pool misses at that stage of execution.
r= Number of rows returned by the call
og= Optimizer goal – 1=ALL_ROWS, 2=FIRST_ROWS (and FIRST_ROWS_n), 3=RULE, 4=CHOOSE
XCTEND rlbk=0 indicates that the client issued a COMMIT, rd_only=1 indicates that no information changed in the database as a result of the COMMIT
ela= is the elapsed time in 1/100 of a second on 8.1.7.4 and earlier, and in 1/1,000,000 of a second on versions after 8.1.7.4.
p1= meaning depends on the wait event
p2= meaning depends on the wait event
p3= meaning depends on the wait event

STAT lines – the row source execution plan:
id= line identifier
cnt= number of rows returned or processed
pid= parent operation identifier – used to determine indentation of the plan
obj= object id of the object referenced at that stage of the plan

Putting the pieces together, it is possible to do the following analysis of a raw 10046 extended SQL trace file:

PARSING IN CURSOR #12 len=170 dep=0 uid=31 oct=3 lid=31 tim=768609360 hv=205969412 ad='a64cba88'
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2
END OF STMT
PARSE #12:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768609356
BINDS #12:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
  kxsbbbfp=151423d0  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
  kxsbbbfp=151423e8  bln=22  avl=03  flg=01
  value=81000
EXEC #12:c=0,e=807,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768611110
WAIT #12: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768611226
WAIT #12: nam='db file sequential read' ela= 184 file#=4 block#=1779171 blocks=1 obj#=114178 tim=768611561
WAIT #12: nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046
WAIT #12: nam='db file sequential read' ela= 103 file#=4 block#=1138380 blocks=1 obj#=114177 tim=768612399
WAIT #12: nam='db file sequential read' ela= 87 file#=4 block#=1754469 blocks=1 obj#=114177 tim=768612648
WAIT #12: nam='db file sequential read' ela= 88 file#=4 block#=1138382 blocks=1 obj#=114177 tim=768612865
WAIT #12: nam='db file sequential read' ela= 81 file#=4 block#=1138374 blocks=1 obj#=114176 tim=768613103
FETCH #12:c=0,e=2195,p=10,cr=51,cu=0,mis=0,r=14,dep=0,og=1,tim=768613513
WAIT #12: nam='SQL*Net message from client' ela= 3432 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768617150
STAT #12 id=1 cnt=14 pid=0 pos=1 obj=0 op='FILTER  (cr=51 pr=10 pw=0 time=2170 us)'
STAT #12 id=2 cnt=14 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)'
STAT #12 id=3 cnt=14 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)'
STAT #12 id=4 cnt=14 pid=3 pos=1 obj=114178 op='TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)'
STAT #12 id=5 cnt=14 pid=2 pos=2 obj=114176 op='TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)'
STAT #12 id=6 cnt=14 pid=5 pos=1 obj=114177 op='INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)'

A simple walk through of the trace file, mapping the trace file to a timeline (this is output from my Toy Project for Performance Tuning):

Cursor 12   Ver 1   Parse at 0.000000
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

Cursor 12   Ver 1   Parse at -0.000004 (Parse to Parse -0.000004),CPU Time 0.000000,
            Elapsed Time 0.000029,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Cursor 12   Ver 1 Execute at 0.001750 (Parse to Exec  0.001750),CPU Time 0.000000,
            Elapsed Time 0.000807,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 12   Ver 1            0.001866  0.000004   SQL*Net message to client
Cursor 12   Ver 1            0.002201  0.000184   db file sequential read
Cursor 12   Ver 1            0.002686  0.000213   db file scattered read
Cursor 12   Ver 1            0.003039  0.000103   db file sequential read
Cursor 12   Ver 1            0.003288  0.000087   db file sequential read
Cursor 12   Ver 1            0.003505  0.000088   db file sequential read
Cursor 12   Ver 1            0.003743  0.000081   db file sequential read
Cursor 12   Ver 1   Fetch at 0.004153 (Parse to Fetch 0.004153),CPU Time 0.000000,
            Elapsed Time 0.002195,Rows Retrievd 14,Blks from Buff 51,Blks from Disk 10
Cursor 12   Ver 1            0.007790  0.003432   SQL*Net message from client

Sometimes mapping the trace file to a timeline is not the best approach, but understanding the role of a specific SQL statement is more critical to understanding the cause of a performance problem (this is output from my Toy Project for Performance Tuning):

Similar SQL Statements in Group: 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|

Cursor 12   Ver 1   Parse at 0.000000  Similar Cnt 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
  CLOCK S 98.67%
|++++++++++++++++++++|

SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

      (Rows 14)   FILTER  (cr=51 pr=10 pw=0 time=2170 us)
      (Rows 14)    NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)
      (Rows 14)     SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)
      (Rows 14)      TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)
      (Rows 14)     TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)
      (Rows 14)      INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)

Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Of course, if the STATISTICS_LEVEL parameter is set to ALL, or a GATHER_PLAN_STATISTICS hint is provided, the following will retrieve the actual execution plan for the test query, if executed immediately after the test query:

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

The output of the above for this SQL statement follows:

SQL_ID  bkhdgq864dq04, child number 0
-------------------------------------
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE       EXISTS (       SELECT         1       FROM         T8       WHERE        
T8.C1=T7.C1)    AND T7.C1 BETWEEN :1 AND :2

Plan hash value: 1996673128

--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|*  1 |  FILTER                       |              |      1 |        |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   2 |   NESTED LOOPS                |              |      1 |      1 |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   3 |    SORT UNIQUE                |              |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |  9216 |  9216 | 8192  (0)|
|*  4 |     TABLE ACCESS FULL         | T8           |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |       |       |          |
|   5 |    TABLE ACCESS BY INDEX ROWID| T7           |     14 |      1 |     14 |00:00:00.01 |      44 |      4 |       |       |          |
|*  6 |     INDEX UNIQUE SCAN         | SYS_C0020535 |     14 |      1 |     14 |00:00:00.01 |      30 |      3 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:1<=:2)
   4 - filter(("T8"."C1">=:1 AND "T8"."C1"<=:2))
   6 - access("T8"."C1"="T7"."C1")
       filter(("T7"."C1"<=:2 AND "T7"."C1">=:1))

The raw 10046 Extended SQL trace offers several advantages over the DBMS_XPLAN output if the P1, P2, and P3 values from the wait events are examined closely:

nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046

In the above, a multi-block read from disk requiring 0.000213 seconds of absolute file number 4, starting at block 1779172, and extending for 5 blocks was performed.  The blocks belong to object ID 114178 and happened at the trace file’s sequential time of 768612046, which may be referenced to the sequential time of other lines in the trace file.

Much more information about 10046 extended SQL traces is provided in the the chapters I co-wrote for the “Expert Oracle Practices: Oracle Database Administration from the Oak Table” book.