FIRST_ROWS_n Optimizer Mode – What is Wrong with this Statement?

8 06 2014

June 8, 2014

It has been nearly two years since I last wrote a review of an Oracle Database related book, although I have recently written reviews of two Microsoft Exchange Server 2013 books and a handful of security cameras in the last two years.  My copy of the second edition of the “Troubleshooting Oracle Performance” book arrived yesterday, so I have been spending some time reading the new edition and comparing it with a PDF version of the first edition.  My initial impressions of the second edition, based on the first 30 pages, are almost entirely positive, although I did find one glitch in the second edition so far.

At the top of page 27 is the following caution, which did not appear in the first edition of the book:

“As the previous example shows, the optimizer_mode column doesn’t show the right value for child number 1. In fact, the column shows FIRST_ROWS instead of FIRST_ROWS_1. The same behavior can be observed with FIRST_ROWS_10, FIRST_ROWS_100, and FIRST_ROWS_1000 as well.  This fact leads to the potential problem that even though the execution environment is different, the SQL engine doesn’t distinguish that difference. As a result, a child cursor might be incorrectly shared.”

So, what is wrong with the above statement?  The above statement, if true, would seem to indicate a bug in Oracle Database, one that has potentially serious performance side-effects; the opening paragraph of the “Troubleshooting Oracle Performance” book states, “Performance is not merely optional, though; it is a key property of an application,” so as an extension, possibly a performance problem should be addressed in a similar fashion as a bug.  I wrote the following into my notes about the above quoted caution section from the book:

This statement might be incorrect, the OPTIMIZER_ENV_HASH_VALUE column in V$SQL should show a different value if the OPTIMIZER_MODE changes from FIRST_ROWS_1 to FIRST_ROWS_1000 and the same SQL statement is executed a second time.

So, I set up a test case to determine whether the above caution quote from the book is correct, or if what I wrote into my notes about the book is accurate.  Actually, both of the above seemingly mutually exclusive statements are correct based on the results of my test case script.  So, how is that possible?  The key is whether or not the SQL statement’s cursor is flushed out of the library cache, or if the child cursor is somehow marked as unshareable (possibly due to statistics collection) between the two executions of the same SQL statement with different FIRST_ROWS_n OPTIMIZER_MODE parameter values.  The  OPTIMIZER_ENV_HASH_VALUE column in V$SQL will be different (at least in Oracle Database 11.2.0.1) if the OPTIMIZER_MODE changes from FIRST_ROWS_1 to FIRST_ROWS_1000 and a hard parse is required, but the change of the OPTIMIZER_MODE from the first value to the second is NOT sufficient to force that hard parse.

The statement found in the “Troubleshooting Oracle Performance” book is correct, so what is wrong with the statement?  If performance problems are considered bugs, then this particular issue seems to point to a bug in Oracle Database, where an opportunity to re-optimize a SQL statement is missed.  Possibly equally important to recognize is that the OPTIMIZER_ENV_HASH_VALUE that is found in V$SQL is NOT used to determine if a SQL statement must be re-optimized (at least in Oracle Database 11.2.0.1) because the changed OPTIMIZER_MODE resulted in a different OPTIMIZER_ENV_HASH_VALUE when a hard parse happens.

So, how is this seemingly minor hard parsing issue a potential problem?  Consider a case where Oracle’s query optimizer should predict that the cardinality of an operation will be 990 rows.  With the OPTIMIZER_MODE set to FIRST_ROWS_1000, the query optimizer will optimize the SQL statement just as if the OPTIMIZER_MODE were set to ALL_ROWS because the predicted cardinality is less than 1000.  So, the optimizer might correctly select to perform a full table scan; while with the OPTIMIZER_MODE set to FIRST_ROWS_1, the predicted cardinality for the same operation might be just 2 (or 1), thus leading to a possibly inefficient index access path if one exists.

If the quote on page 27 does not contain the glitch that I found in the first 30 pages of the book, where is the glitch?  I actually found two glitches in the first 27 pages of the book, but I will not mention those glitches at this time.

It might be interesting to see if later releases of Oracle Database actually do force a hard parse for a SQL statement when the OPTIMIZER_MODE changes from FIRST_ROWS_1 to FIRST_ROWS_1000. (or if two sessions have the different FIRST_ROWS_n OPTIMIZER_MODE settings, and each execute the same SQL statement). Here is the test script that I constructed:

DROP TABLE T1 PURGE;
 
SET LINESIZE 140
SET PAGESIZE 1000
SET TRIMSPOOL ON
 
SELECT
  VERSION
FROM
  V$INSTANCE;
 
CREATE TABLE T1 AS
SELECT
  ROWNUM C1,
  MOD(ROWNUM,500) C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;
 
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1')
 
ALTER SYSTEM FLUSH SHARED_POOL;
 
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1;
 
SELECT C1 FROM T1 WHERE C2=2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
SELECT
  SQL_ID,
  CHILD_NUMBER,
  OPTIMIZER_MODE,
  OPTIMIZER_ENV_HASH_VALUE,
  PLAN_HASH_VALUE
FROM
  V$SQL
WHERE
  SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1000;
 
SELECT C1 FROM T1 WHERE C2=2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
SELECT
  SQL_ID,
  CHILD_NUMBER,
  OPTIMIZER_MODE,
  OPTIMIZER_ENV_HASH_VALUE,
  PLAN_HASH_VALUE
FROM
  V$SQL
WHERE
  SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SELECT
  CHILD_NUMBER,
  NAME,
  VALUE
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='bqx2tj39jw1f5'
  AND NAME='optimizer_mode'
ORDER BY
  NAME;
 
ALTER SYSTEM FLUSH SHARED_POOL;
 
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1000;
 
SELECT C1 FROM T1 WHERE C2=2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
SELECT
  SQL_ID,
  CHILD_NUMBER,
  OPTIMIZER_MODE,
  OPTIMIZER_ENV_HASH_VALUE,
  PLAN_HASH_VALUE
FROM
  V$SQL
WHERE
  SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1;
 
SELECT C1 FROM T1 WHERE C2=2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
SELECT
  SQL_ID,
  CHILD_NUMBER,
  OPTIMIZER_MODE,
  OPTIMIZER_ENV_HASH_VALUE,
  PLAN_HASH_VALUE
FROM
  V$SQL
WHERE
  SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SELECT
  CHILD_NUMBER,
  NAME,
  VALUE
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='bqx2tj39jw1f5'
  AND NAME='optimizer_mode'
ORDER BY
  NAME;

The script is broken into two halves, with an ALTER SYSTEM FLUSH SHARED_POOL; separating the two halves of the script.  The execution plan is displayed after each execution of the test SQL statement to show the optimizer’s predicted cardinality for the TABLE ACCESS FULL operation as well as the calculated cost and estimated number of bytes returned from that operation.  The query optimizer’s calculated cost for an operation could cause the execution plan to change, although such a change could not happen in this test case script.

Below is the output that I received on Oracle Database 11.2.0.1 for the first half of the script.  Note that I have removed excessive blank lines and the output of the test SQL statement.  Notice that the OPTIMIZER_ENV_HASH_VALUE is displayed as 1002285490 when starting with the FIRST_ROWS_1 OPTIMIZER_MODE:

SQL> ALTER SYSTEM FLUSH SHARED_POOL;
 
System altered.
 
SQL> ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1;
 
Session altered.
 
SQL> SELECT C1 FROM T1 WHERE C2=2;
 
20 rows selected.
 
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  bqx2tj39jw1f5, child number 0
-------------------------------------
SELECT C1 FROM T1 WHERE C2=2
 
Plan hash value: 3617692013
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     2 |    16 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=2)
 
SQL> SELECT
  2    SQL_ID,
  3    CHILD_NUMBER,
  4    OPTIMIZER_MODE,
  5    OPTIMIZER_ENV_HASH_VALUE,
  6    PLAN_HASH_VALUE
  7  FROM
  8    V$SQL
  9  WHERE
 10    SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SQL_ID        CHILD_NUMBER OPTIMIZER_ OPTIMIZER_ENV_HASH_VALUE PLAN_HASH_VALUE
------------- ------------ ---------- ------------------------ ---------------
bqx2tj39jw1f5            0 FIRST_ROWS               1002285490      3617692013
 
SQL> ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1000;
 
Session altered.
 
SQL> SELECT C1 FROM T1 WHERE C2=2;
 
20 rows selected.
 
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  bqx2tj39jw1f5, child number 0
-------------------------------------
SELECT C1 FROM T1 WHERE C2=2
 
Plan hash value: 3617692013
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     2 |    16 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=2)
 
SQL> SELECT
  2    SQL_ID,
  3    CHILD_NUMBER,
  4    OPTIMIZER_MODE,
  5    OPTIMIZER_ENV_HASH_VALUE,
  6    PLAN_HASH_VALUE
  7  FROM
  8    V$SQL
  9  WHERE
 10    SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SQL_ID        CHILD_NUMBER OPTIMIZER_ OPTIMIZER_ENV_HASH_VALUE PLAN_HASH_VALUE
------------- ------------ ---------- ------------------------ ---------------
bqx2tj39jw1f5            0 FIRST_ROWS               1002285490      3617692013
 
SQL>
SQL> SELECT
  2    CHILD_NUMBER,
  3    NAME,
  4    VALUE
  5  FROM
  6    V$SQL_OPTIMIZER_ENV
  7  WHERE
  8    SQL_ID='bqx2tj39jw1f5'
  9    AND NAME='optimizer_mode'
 10  ORDER BY
 11    NAME;
 
CHILD_NUMBER NAME                                     VALUE
------------ ---------------------------------------- -------------------------
           0 optimizer_mode                           first_rows_1

Below is the output that I received on Oracle Database 11.2.0.1 for the second half of the script.  Note that I have removed excessive blank lines and the output of the test SQL statement.  Notice that the OPTIMIZER_ENV_HASH_VALUE is displayed as 4271299772 (rather than 1002285490 as was seen above) when starting with the FIRST_ROWS_1000 OPTIMIZER_MODE:

SQL> ALTER SYSTEM FLUSH SHARED_POOL;
 
System altered.
 
SQL> ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1000;
 
Session altered.
 
SQL> SELECT C1 FROM T1 WHERE C2=2;
 
20 rows selected.
 
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  bqx2tj39jw1f5, child number 0
-------------------------------------
SELECT C1 FROM T1 WHERE C2=2
 
Plan hash value: 3617692013
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     3 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |    20 |   160 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=2)
 
SQL> SELECT
  2    SQL_ID,
  3    CHILD_NUMBER,
  4    OPTIMIZER_MODE,
  5    OPTIMIZER_ENV_HASH_VALUE,
  6    PLAN_HASH_VALUE
  7  FROM
  8    V$SQL
  9  WHERE
 10    SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SQL_ID        CHILD_NUMBER OPTIMIZER_ OPTIMIZER_ENV_HASH_VALUE PLAN_HASH_VALUE
------------- ------------ ---------- ------------------------ ---------------
bqx2tj39jw1f5            0 FIRST_ROWS               4271299772      3617692013
 
SQL> ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_1;
 
Session altered.
 
SQL> SELECT C1 FROM T1 WHERE C2=2;
 
20 rows selected.
 
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  bqx2tj39jw1f5, child number 0
-------------------------------------
SELECT C1 FROM T1 WHERE C2=2
 
Plan hash value: 3617692013
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     3 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |    20 |   160 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=2)
 
SQL> SELECT
  2    SQL_ID,
  3    CHILD_NUMBER,
  4    OPTIMIZER_MODE,
  5    OPTIMIZER_ENV_HASH_VALUE,
  6    PLAN_HASH_VALUE
  7  FROM
  8    V$SQL
  9  WHERE
 10    SQL_TEXT='SELECT C1 FROM T1 WHERE C2=2';
 
SQL_ID        CHILD_NUMBER OPTIMIZER_ OPTIMIZER_ENV_HASH_VALUE PLAN_HASH_VALUE
------------- ------------ ---------- ------------------------ ---------------
bqx2tj39jw1f5            0 FIRST_ROWS               4271299772      3617692013
 
SQL> SELECT
  2    CHILD_NUMBER,
  3    NAME,
  4    VALUE
  5  FROM
  6    V$SQL_OPTIMIZER_ENV
  7  WHERE
  8    SQL_ID='bqx2tj39jw1f5'
  9    AND NAME='optimizer_mode'
 10  ORDER BY
 11    NAME;
 
CHILD_NUMBER NAME                                     VALUE
------------ ---------------------------------------- -------------------------
           0 optimizer_mode                           first_rows_1000

As repeatedly demonstrated in the “Troubleshooting Oracle Performance” book, testing theories is important.  In this case, I learned something new when what was mentioned in the book did not agree with what I recalled as being Oracle Database behavior.  I anticipate that the learning (or re-learning) process will continue as I quietly question the statements found in the book.  There is enough new material in the second edition of the book to make it a compulsive buy for people who already own the first edition (I own the print hard copy and the companion PDF versions of the first edition).





Parallel Parking – What is causing the Query to be Executed in Parallel?

31 07 2012

July 31, 2012

I encountered an interesting OTN thread that caused me to stop and think for a couple of minutes.  The OP (original poster) in the OTN thread wondered why parallel execution was used for a query when the parallel degree for the table accessed by the query and its indexes were specified to have a parallel degree of 1.  For some reason, while the OP provided DBMS_XPLAN generated execution plan output, the Note section from the output was not included in the OTN post.  With parallel execution enabled in the session (ALTER SESSION ENABLE PARALLEL QUERY;) the execution plan showed a cost of 2,025.  With parallel execution disabled in the session (ALTER SESSION DISABLE PARALLEL QUERY;) the execution plan showed a cost of 36,504.  From this, we can determine that the parallel degree for the query is 20 (36504 / 2025 / 0.9 = 20.03).  The table is partitioned on a date column, apparently partitioned by month.

Interesting?

Could the parallel execution be caused by the PARALLEL_AUTOMATIC_TUNING parameter’s value?  The DBMS_XPLAN output indicates that the OP is using Oracle Database 11.2.0.2, where that parameter is deprecated.  What about the PARALLEL_DEGREE_POLICY parameter?  When that parameter is set to AUTO, the query optimizer is free to plan a parallel execution for a query, even when the tables (and their indexes) accessed by the query are set to a parallel degree of 1.

A table creation script for a couple of tests (note that the table created in the test case is using INTERVAL partitioning using an approach very similar to that found on page 576 in the book Expert Oracle Database Architecture: Oracle Database Programming 9i, 10g, and 11g Techniques and Solutions, Second Edition except that I have a DATE column in the table rather than a TIMESTAMP column):

DROP TABLE T1 PURGE;

CREATE TABLE T1 (
  C1 NUMBER,
  C2 VARCHAR2(10),
  C3 DATE,
  C4 VARCHAR2(20))
  PARTITION BY RANGE(C3)
  INTERVAL(NUMTOYMINTERVAL(1, 'MONTH'))
  ( PARTITION p0 VALUES LESS THAN (TO_DATE('1-1-2007', 'DD-MM-YYYY')));

INSERT INTO
  T1
SELECT
  ROWNUM,
  RPAD(ROWNUM,10,'A'),
  TRUNC(SYSDATE)+MOD(ROWNUM-1,3000),
  RPAD('A',20,'A')
FROM
  (SELECT
    1 C1
  FROM
    DUAL
  CONNECT BY
    LEVEL<100000),
  (SELECT
    1 C1
  FROM
    DUAL
  CONNECT BY
    LEVEL<1000);

COMMIT; 

Let’s see, a Cartesian join between a rowsource with 1,000 rows and a rowsource with 100,000 rows produces (on 11.2.0.1, 11.2.0.2, and 11.2.0.3):

99899001 rows created. 

Interesting, I might have to investigate that oddity at a later time.  I was expecting 1,000 * 100,000 = 100,000,000 rows.

Let’s try a simple test:

select count(*) from t1;

SET LINESIZE 140
SET PAGESIZE 1000

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

SQL_ID  5bc0v4my7dvr5, child number 0
-------------------------------------
select count(*) from t1

Plan hash value: 2705263620

-------------------------------------------------------------------------------------
| Id  | Operation            | Name | Rows  | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |       | 59271 (100)|          |       |       |
|   1 |  SORT AGGREGATE      |      |     1 |            |          |       |       |
|   2 |   PARTITION RANGE ALL|      |   115M| 59271   (2)| 00:07:55 |     1 |1048575|
|   3 |    TABLE ACCESS FULL | T1   |   115M| 59271   (2)| 00:07:55 |     1 |1048575|
-------------------------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement (level=2)

1,048,575 partitions… I was expecting about 100 partitions because there should be 3,000 distinct dates in column C3.  Maybe I should find some time to investigate?  Moving on…

To test the theory that the unexpected parallel execution might be caused by a non-default value for the PARALLEL_DEGREE_POLICY parameter, we need to first use the DBMS_RESOURCE_MANAGER.CALIBRATE_IO procedure to indicate performance metrics for the server.  To save time, I found a blog article (by another OakTable Network member) that shows a back-door approach that does not require the CALIBRATE_IO procedure (the usual warnings apply here – we are technically modifying objects in the SYS schema).  The back-door approach, when connected as the SYS user (note that the script first selects from RESOURCE_IO_CALIBRATE$ so that if values are currently present, those values may be restored after testing completes):

SELECT
  *
FROM
  RESOURCE_IO_CALIBRATE$;

DELETE FROM
  RESOURCE_IO_CALIBRATE$;

INSERT INTO
  RESOURCE_IO_CALIBRATE$
VALUES(
  CURRENT_TIMESTAMP,
  CURRENT_TIMESTAMP,
  0,
  0,
  200,
  0,
  0);

COMMIT; 

I will start by posting results that I obtained from Oracle Database 11.2.0.3.

Let’s try the previous select from T1 again (note that I am first setting the PARALLEL_DEGREE_POLICY parameter at the session level to its default value):

ALTER SESSION SET PARALLEL_DEGREE_POLICY=MANUAL;

select count(*) from t1;

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

SQL_ID  5bc0v4my7dvr5, child number 0
-------------------------------------
select count(*) from t1

Plan hash value: 2705263620

-------------------------------------------------------------------------------------
| Id  | Operation            | Name | Rows  | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |       | 59271 (100)|          |       |       |
|   1 |  SORT AGGREGATE      |      |     1 |            |          |       |       |
|   2 |   PARTITION RANGE ALL|      |   115M| 59271   (2)| 00:00:03 |     1 |1048575|
|   3 |    TABLE ACCESS FULL | T1   |   115M| 59271   (2)| 00:00:03 |     1 |1048575|
-------------------------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement (level=2)

Let’s try again with a modified value for that parameter:

ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;

select count(*) from t1;

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

SQL_ID  5bc0v4my7dvr5, child number 2
-------------------------------------
select count(*) from t1

Plan hash value: 974985148

------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name     | Rows  | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |          |       | 32790 (100)|          |       |       |        |      |            |
|   1 |  SORT AGGREGATE        |          |     1 |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR       |          |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM) | :TQ10000 |     1 |            |          |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE     |          |     1 |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR |          |   115M| 32790   (2)| 00:00:02 |     1 |1048575|  Q1,00 | PCWC |            |
|*  6 |       TABLE ACCESS FULL| T1       |   115M| 32790   (2)| 00:00:02 |     1 |1048575|  Q1,00 | PCWP |            |
------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   6 - access(:Z>=:Z AND :Z<=:Z)

Note
-----
   - dynamic sampling used for this statement (level=2)
   - automatic DOP: Computed Degree of Parallelism is 2 

In the above, the Note section indicates that the automatic degree of parallelism was set to 2, and that dynamic sampling was performed at level 2.  I have yet to collect statistics on table T1, so that explains why dynamic sampling was used when the query was executed with and without parallel execution.  If you take a close look at the OTN thread that is linked to at the start of this blog article, you will see that the dynamic sampling level was set to 6, but only for the parallel execution.  The simple answer for this change in behavior is that it is expected, as described in this article by Maria Colgan (another OakTable Network member).  We can confirm that the cost calculation is working as expected: 59271 / 32790 / 0.9 = 2.01.

Let’s try executing the query of table T1 using a WHERE clause that is similar to what is found in the OTN thread:

ALTER SESSION SET PARALLEL_DEGREE_POLICY=MANUAL;

select count(*) from t1
WHERE C3 BETWEEN to_date('01/08/2012', 'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy');

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

SQL_ID  1ggk1hy0r22kt, child number 0
-------------------------------------
select count(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2744578615

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |       |       |   235K(100)|          |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     9 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      |  2286K|    19M|   235K(100)| 00:00:10 |    69 |    71 |
|*  3 |    TABLE ACCESS FULL      | T1   |  2286K|    19M|   235K(100)| 00:00:10 |    69 |    71 |
--------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "C3"<=TO_DATE(' 2012-10-14 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - dynamic sampling used for this statement (level=2) 

Let’s try again, this time with the non-default value for the PARALLEL_DEGREE_POLICY:

ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;

select count(*) from t1
WHERE C3 BETWEEN to_date('01/08/2012', 'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy');

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

SQL_ID  1ggk1hy0r22kt, child number 1
-------------------------------------
select count(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2946076746

--------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |          |       |       |   835K(100)|          |       |       |        |      |            |
|   1 |  SORT AGGREGATE        |          |     1 |     9 |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR       |          |       |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM) | :TQ10000 |     1 |     9 |            |          |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE     |          |     1 |     9 |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR |          |   112M|   968M|   835K(100)| 00:00:33 |    69 |    71 |  Q1,00 | PCWC |            |
|*  6 |       TABLE ACCESS FULL| T1       |   112M|   968M|   835K(100)| 00:00:33 |    69 |    71 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      ALL_ROWS
      SHARED(16)
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   6 - access(:Z>=:Z AND :Z<=:Z)
       filter(("C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND "C3"<=TO_DATE(' 2012-10-14
              00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - dynamic sampling used for this statement (level=2)
   - automatic DOP: Computed Degree of Parallelism is 16 because of degree limit 

Notice anything strange… really strange about the above output?  The new version of the query is limited to just 3 partitions, yet the calculated cost of the non-parallel execution is approximately 235,000 (much higher than the calculated cost of selecting from the full table without the WHERE clause) – that is just one reason why relying on cost for tuning performance purposes (as suggested by a couple of books) is potentially misleading.  But wait, the plan using parallel execution with an automatic degree of parallelism of 16 has a plan cost of approximately 835,000 and the optimizer still selected that plan!  I strongly suspect that a query optimizer bug caused a miscalculation of the plan cost; I could not reproduce the odd cost calculation on Oracle Database 11.2.0.1 or 11.2.0.2.  Still suspicious of the cost in the execution plan, at the end of testing I dropped and recreated the table.  After recreating the test table, the following execution plan was generated with a less crazy cost calculation:

SQL_ID  1ggk1hy0r22kt, child number 1
-------------------------------------
select count(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2946076746

--------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |          |       |       | 23822 (100)|          |       |       |        |      |            |
|   1 |  SORT AGGREGATE        |          |     1 |     9 |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR       |          |       |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM) | :TQ10000 |     1 |     9 |            |          |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE     |          |     1 |     9 |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR |          |  2286K|    19M| 23822 (100)| 00:00:01 |    69 |    71 |  Q1,00 | PCWC |            |
|*  6 |       TABLE ACCESS FULL| T1       |  2286K|    19M| 23822 (100)| 00:00:01 |    69 |    71 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      ALL_ROWS
      SHARED(11)
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   6 - access(:Z>=:Z AND :Z<=:Z)
       filter(("C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND "C3"<=TO_DATE(' 2012-10-14
              00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - dynamic sampling used for this statement (level=2)
   - automatic DOP: Computed Degree of Parallelism is 11 

Let’s double-check the calculated cost in the parallel execution plan: 235,000 / 23822 / 0.9 = 10.96 – that calculated cost is consistent with the Computed Degree of Parallelism.

I am curious about whether or not dynamic sampling might affect just the parallel execution.  Let’s collect statistics on table T1 with 100% sampling (note that it could take a long time for this statistics collection to complete):

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',ESTIMATE_PERCENT=>NULL)

Let’s try our query again (note that I have forced a hard parse of the SQL statement by changing the capitalization of a couple parts of the SQL statement):

ALTER SESSION SET PARALLEL_DEGREE_POLICY=MANUAL;

SELECT COUNT(*) from t1
WHERE C3 BETWEEN to_date('01/08/2012', 'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy');

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

SQL_ID  2q2uz15vyzqsy, child number 1
-------------------------------------
SELECT COUNT(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2744578615

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |       |       |  1816 (100)|          |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      |  2531K|    19M|  1816   (3)| 00:00:01 |    69 |    71 |
|*  3 |    TABLE ACCESS FULL      | T1   |  2531K|    19M|  1816   (3)| 00:00:01 |    69 |    71 |
--------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("C3"<=TO_DATE(' 2012-10-14 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Notice in the above that the execution plan for the non-parallel execution has a calculated cost that decreased from 235,000 to just 1,816, even though the same Pstart (69) and Pstop (71) columns are listed, and approximately the same estimated number of rows (~2,286,000 vs ~2,531,000) are expected to be returned.  So, if you are attempting to performance tune by attempting to simply reduce the calculated cost of a query (not a valid approach), you might be lead to believe that collecting statistics improved the performance of this query by a factor of 129.4 (the performance did improve a little due to dynamic sampling no longer being required, but the performance did not improve nearly that much).

Let’s try the query again with a modified value for the PARALLEL_DEGREE_POLICY parameter:

ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;

select COUNT(*) from t1
WHERE C3 BETWEEN to_date('01/08/2012', 'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy');

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

SQL_ID  2q2uz15vyzqsy, child number 0
-------------------------------------
SELECT COUNT(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2744578615

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |       |       |  1816 (100)|          |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      |  2531K|    19M|  1816   (3)| 00:00:01 |    69 |    71 |
|*  3 |    TABLE ACCESS FULL      | T1   |  2531K|    19M|  1816   (3)| 00:00:01 |    69 |    71 |
--------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.3')
      DB_VERSION('11.2.0.3')
      ALL_ROWS
      NO_PARALLEL
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("C3"<=TO_DATE(' 2012-10-14 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

The Note section indicates that parallel execution was considered, but not used.  So, after collecting statistics, the parallel degree for this query decreased from 16 (or 11 in the non-bug affected execution plan) to 1 – a non-parallel execution.

The above output was generated with Oracle Database 11.2.0.3 using the following system (CPU) statistics:

COLUMN PNAME FORMAT A14
COLUMN PVAL2 FORMAT A20

SELECT
  PNAME,
  PVAL1,
  PVAL2
FROM
  SYS.AUX_STATS$;

PNAME               PVAL1 PVAL2
-------------- ---------- ----------------
STATUS                    COMPLETED
DSTART                    07-11-2012 15:11
DSTOP                     07-11-2012 15:11
FLAGS                   1
CPUSPEEDNW     1720.20725
IOSEEKTIM              10
IOTFRSPEED           4096
SREADTIM                8
MREADTIM               10
CPUSPEED             2664
MBRC                   16
MAXTHR           19181568
SLAVETHR

While experimenting with Oracle Database 11.2.0.2, I used the following system (CPU) statistics:

COLUMN PNAME FORMAT A14
COLUMN PVAL2 FORMAT A20

SELECT
  PNAME,
  PVAL1,
  PVAL2
FROM
  SYS.AUX_STATS$;

PNAME               PVAL1 PVAL2
-------------- ---------- ----------------
STATUS                    COMPLETED
DSTART                    02-29-2012 19:07
DSTOP                     02-29-2012 19:07
FLAGS                   1
CPUSPEEDNW     2116.57559
IOSEEKTIM              10
IOTFRSPEED           4096
SREADTIM               .4
MREADTIM               .8
CPUSPEED             1922
MBRC                   16
MAXTHR          155910144
SLAVETHR

11.2.0.2 showed the following execution plan after collecting statistics for table T1 and setting the PARALLEL_DEGREE_POLICY parameter to AUTO:

SQL_ID  81dw7f2yz0jxp, child number 1
-------------------------------------
select COUNT(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2744578615

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |       |       |  4082 (100)|          |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      |  2531K|    19M|  4082  (29)| 00:00:01 |    69 |    71 |
|*  3 |    TABLE ACCESS FULL      | T1   |  2531K|    19M|  4082  (29)| 00:00:01 |    69 |    71 |
--------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      ALL_ROWS
      NO_PARALLEL
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("C3"<=TO_DATE(' 2012-10-14 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

In the above execution plan, notice that the calculated cost is 4,082 (this is higher than the calculated cost returned by Oracle Database 11.2.0.3).  The SREADTIM and MREADTIM system statistics were manually set to very small numbers – due to a bug in Oracle Database 11.2.0.1 and 11.2.0.2 these system statistics could be set to much large values, such as 2,491 and 9,163, respectively.  What might happen to the calculated cost if we were to increase the SREADTIM and MREADTIM system statistics by a factor of 10?  Such a change would indicate to the query optimizer that each disk access will required 10 times longer to complete.  Should the calculated cost of this query increase or decrease after changing the system statistics?

First, let’s manually alter the value of the system statistics:

EXEC DBMS_STATS.SET_SYSTEM_STATS('SREADTIM',4)
EXEC DBMS_STATS.SET_SYSTEM_STATS('MREADTIM',8)

Next, execute the query and display the execution plan (notice that capitalization of the word SELECT was changed to force a hard parse of the query):

ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;

SELECT COUNT(*) from t1
WHERE C3 BETWEEN to_date('01/08/2012', 'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy');

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

SQL_ID  2q2uz15vyzqsy, child number 1
-------------------------------------
SELECT COUNT(*) from t1 WHERE C3 BETWEEN to_date('01/08/2012',
'dd/mm/yyyy') and to_date('14/10/2012', 'dd/mm/yyyy')

Plan hash value: 2744578615

--------------------------------------------------------------------------------------------------
| Id  | Operation                 | Name | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |      |       |       |  3020 (100)|          |       |       |
|   1 |  SORT AGGREGATE           |      |     1 |     8 |            |          |       |       |
|   2 |   PARTITION RANGE ITERATOR|      |  2531K|    19M|  3020   (4)| 00:00:01 |    69 |    71 |
|*  3 |    TABLE ACCESS FULL      | T1   |  2531K|    19M|  3020   (4)| 00:00:01 |    69 |    71 |
--------------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      ALL_ROWS
      NO_PARALLEL
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T1"@"SEL$1")
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("C3"<=TO_DATE(' 2012-10-14 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
              "C3">=TO_DATE(' 2012-08-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')))

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

Notice the changes in the execution plan?  The calculated cost shown in the execution plan decreased from 4,082 to 3,020, and the %CPU for the third line in the execution plan decreased from 29 to 4.  Why did the calculated cost decrease when the optimizer is informed that disk accesses require 10 times as long to complete?  For the answer, take a look at this blog article written by Randolf Geist (another OakTable Network member).

OK, so I drifted a bit from the focus of the OTN message thread that provoked this article.  What do you think caused parallel execution to be used when the OP executed the query found in the OTN thread?





Parallel Execution Challenge – It’s About Time

8 07 2012

July 8, 2012

As I was reading a book, I saw a comment essentially stating that with multiple CPUs/cores, parallel execution will be faster than serial execution of the same query.  The book provided a test case – I decided to change around the test case a bit so that the results were a bit more fair, and then I performed a bit of testing using the sample database data that Oracle Corporation provides. 

My testing was performed in Oracle Database 11.2.0.1 on 64 bit Windows with a quad core CPU that supports hyperthreading, and two SSD drives in a RAID 0 array (with all scripts executed on the server).  So, is parallel query always faster than serial execution when the server has multiple CPUs/cores?  But wait, that is not the interesting question… not the point of this parallel execution challenge, but still an interesting question.  Here is the test script, which will be executed three times, with the results of the first execution thrown out so that we may eliminate the side effects of the hard parse:

ALTER SESSION SET CURRENT_SCHEMA=SH;
SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN
SET TIMING ON
SET LINESIZE 145
SET PAGESIZE 1000

ALTER SYSTEM FLUSH BUFFER_CACHE;
SELECT /*+ PARALLEL(2) */ S.PROD_ID, S.CUST_ID, S.TIME_ID FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC;

ALTER SYSTEM FLUSH BUFFER_CACHE;
SELECT S.PROD_ID, S.CUST_ID, S.TIME_ID FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC; 

Notice in the above that the test case performs the parallel execution first, with a degree of parallelism of 2, and then executes the same query without using parallel execution.

Let’s look at the output for the parallel execution:

918843 rows selected.

Elapsed: 00:00:11.97

Execution Plan
----------------------------------------------------------
Plan hash value: 2055439529

-----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation               | Name     | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |          |   918K|    19M|       |   308  (14)| 00:00:04 |       |       |        |      |            |
|   1 |  PX COORDINATOR         |          |       |       |       |            |          |       |       |        |      |            |
|   2 |   PX SEND QC (ORDER)    | :TQ10001 |   918K|    19M|       |   308  (14)| 00:00:04 |       |       |  Q1,01 | P->S | QC (ORDER) |
|   3 |    SORT ORDER BY        |          |   918K|    19M|    31M|   308  (14)| 00:00:04 |       |       |  Q1,01 | PCWP |            |
|   4 |     PX RECEIVE          |          |   918K|    19M|       |   277   (4)| 00:00:04 |       |       |  Q1,01 | PCWP |            |
|   5 |      PX SEND RANGE      | :TQ10000 |   918K|    19M|       |   277   (4)| 00:00:04 |       |       |  Q1,00 | P->P | RANGE      |
|   6 |       PX BLOCK ITERATOR |          |   918K|    19M|       |   277   (4)| 00:00:04 |     1 |    28 |  Q1,00 | PCWC |            |
|   7 |        TABLE ACCESS FULL| SALES    |   918K|    19M|       |   277   (4)| 00:00:04 |     1 |    28 |  Q1,00 | PCWP |            |
-----------------------------------------------------------------------------------------------------------------------------------------

Note
-----
   - Degree of Parallelism is 2 because of hint

Statistics
----------------------------------------------------------
         12  recursive calls
          0  db block gets
       1802  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

918,843 rows selected (not displayed in SQL*Plus due to the AUTOTRACE setting), 1,647 blocks read from disk, 1,802 consistent gets, an estimated cost of 308, and the execution completed in 11.97 seconds.

Let’s take a look at the serial execution output:

918843 rows selected.

Elapsed: 00:00:08.84

Execution Plan
----------------------------------------------------------
Plan hash value: 3803407550

------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       |   918K|    19M|       |  6637   (2)| 00:01:20 |       |       |
|   1 |  SORT ORDER BY       |       |   918K|    19M|    31M|  6637   (2)| 00:01:20 |       |       |
|   2 |   PARTITION RANGE ALL|       |   918K|    19M|       |   499   (4)| 00:00:06 |     1 |    28 |
|   3 |    TABLE ACCESS FULL | SALES |   918K|    19M|       |   499   (4)| 00:00:06 |     1 |    28 |
------------------------------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1718  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

918,843 rows selected (not displayed in SQL*Plus due to the AUTOTRACE setting), 1,647 blocks read from disk, 1,718 consistent gets, an estimated cost of 6,637, and the execution completed in 8.84 seconds.

* The first part of the challenge is to describe how the cost is derived in the above execution plan for the parallel execution.  Here is the easy part of the cost calculation:

cost of serial full table scan / degree of parallel / 0.90
499 / 2 / 0.90 = 277.22

The above calculation is easy to understand, and is explained in this article.  The SORT ORDER BY operation in the parallel query execution plan added 31 to the calculated cost (308 – 277), while the same operation in the serial execution added 6,138 to the calculated cost (6637 – 499).

The first challenge is to describe why the calculated cost of the parallel execution plan is so small compared to the serial execution.

The timing output indicated that the serial execution required 3.13 fewer seconds than the parallel execution.  Let’s look at the results of the third execution of this test case script:

918843 rows selected.

Elapsed: 00:00:10.66

Execution Plan
----------------------------------------------------------
Plan hash value: 2055439529

-----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation               | Name     | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |          |   918K|    19M|       |   308  (14)| 00:00:04 |       |       |        |      |            |
|   1 |  PX COORDINATOR         |          |       |       |       |            |          |       |       |        |      |            |
|   2 |   PX SEND QC (ORDER)    | :TQ10001 |   918K|    19M|       |   308  (14)| 00:00:04 |       |       |  Q1,01 | P->S | QC (ORDER) |
|   3 |    SORT ORDER BY        |          |   918K|    19M|    31M|   308  (14)| 00:00:04 |       |       |  Q1,01 | PCWP |            |
|   4 |     PX RECEIVE          |          |   918K|    19M|       |   277   (4)| 00:00:04 |       |       |  Q1,01 | PCWP |            |
|   5 |      PX SEND RANGE      | :TQ10000 |   918K|    19M|       |   277   (4)| 00:00:04 |       |       |  Q1,00 | P->P |      RANGE |
|   6 |       PX BLOCK ITERATOR |          |   918K|    19M|       |   277   (4)| 00:00:04 |     1 |    28 |  Q1,00 | PCWC |            |
|   7 |        TABLE ACCESS FULL| SALES    |   918K|    19M|       |   277   (4)| 00:00:04 |     1 |    28 |  Q1,00 | PCWP |            |
-----------------------------------------------------------------------------------------------------------------------------------------

Note
-----
   - Degree of Parallelism is 2 because of hint

Statistics
----------------------------------------------------------
         12  recursive calls
          0  db block gets
       1802  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

The above shows the results of the parallel execution.  918,843 rows selected (not displayed in SQL*Plus due to the AUTOTRACE setting), 1,647 blocks read from disk, 1,802 consistent gets, an estimated cost of 308, and completed in 10.66 seconds.  Notice that with the exception of the elapsed time, the statistics are identical to what we saw during the previous execution of the test script.

918843 rows selected.

Elapsed: 00:00:08.48

Execution Plan
----------------------------------------------------------
Plan hash value: 3803407550

------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       |   918K|    19M|       |  6637   (2)| 00:01:20 |       |       |
|   1 |  SORT ORDER BY       |       |   918K|    19M|    31M|  6637   (2)| 00:01:20 |       |       |
|   2 |   PARTITION RANGE ALL|       |   918K|    19M|       |   499   (4)| 00:00:06 |     1 |    28 |
|   3 |    TABLE ACCESS FULL | SALES |   918K|    19M|       |   499   (4)| 00:00:06 |     1 |    28 |
------------------------------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1718  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

The above shows the results of the serial execution. 918,843 rows selected (not displayed in SQL*Plus due to the AUTOTRACE setting), 1,647 blocks read from disk, 1,718 consistent gets, an estimated cost of 6,637, and completed in 8.48 seconds. Notice that with the exception of the elapsed time, the statistics are identical to what we saw during the previous execution of the test script.

The second challenge is to describe why the serial execution completed at least 25% faster than the parallel execution of the same query – this result is counter to what the calculated cost of the execution plans suggest, and counter to what the book claimed.

Maybe we need to look at the result from a different angle.  The book did not use SET TIMING ON as my test case above did, so let’s change the test case again.  This time, we will use the GATHER_PLAN_STATISTICS hint so that the runtime engine will collect the timing and various other statistics, and then use DBMS_XPLAN to display the actual execution plan.  To eliminate the effects of hard parsing, the script will be executed three times with the first execution thrown out.  The new script:

ALTER SESSION SET CURRENT_SCHEMA=SH;
SET AUTOTRACE TRACEONLY STATISTICS
SET TIMING OFF
SET LINESIZE 145
SET PAGESIZE 1000

ALTER SYSTEM FLUSH BUFFER_CACHE;
SELECT /*+ Q1 PARALLEL(2) GATHER_PLAN_STATISTICS */ S.PROD_ID, S.CUST_ID, S.TIME_ID FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC;

ALTER SYSTEM FLUSH BUFFER_CACHE;
SELECT /*+ Q2 GATHER_PLAN_STATISTICS */ S.PROD_ID, S.CUST_ID, S.TIME_ID FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC;

SET AUTOTRACE OFF 

SELECT
  SQL_ID,
  CHILD_NUMBER,
  SUBSTR(SQL_TEXT,1,30) SQL_TEXT
FROM
  V$SQL
WHERE
  SQL_TEXT LIKE 'SELECT /*+ Q%'
ORDER BY
  3,
  1,
  2; 

The last of the above SQL statements simply retrieves the SQL_ID and CHILD_NUMBER for the two previous queries.  For my results, I received the following output from the last of the above SQL statements:

SQL_ID        CHILD_NUMBER SQL_TEXT
------------- ------------ ------------------------------
5p47nbddfn0k7            0 SELECT /*+ Q1 PARALLEL(2) GATH
8k6bdqr09xc8u            0 SELECT /*+ Q2 GATHER_PLAN_STAT 

To display the execution plans with the runtime statistics, we are able to use the following two statements:

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('5p47nbddfn0k7',0,'ALLSTATS LAST +COST'));

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('8k6bdqr09xc8u',0,'ALLSTATS LAST +COST')); 

Here are the autotrace statistics for the parallel execution:

Statistics
----------------------------------------------------------
         12  recursive calls
          0  db block gets
       1802  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

The DBMS_XPLAN generated execution plan for the parallel execution follows:

SQL_ID  5p47nbddfn0k7, child number 0
-------------------------------------
SELECT /*+ Q1 PARALLEL(2) GATHER_PLAN_STATISTICS */ S.PROD_ID,
S.CUST_ID, S.TIME_ID FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC

Plan hash value: 2055439529

-----------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation               | Name     | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |          |      1 |        |   308 (100)|    918K|00:00:00.70 |     116 |     28 |       |       |          |
|   1 |  PX COORDINATOR         |          |      1 |        |            |    918K|00:00:00.70 |     116 |     28 |       |       |          |
|   2 |   PX SEND QC (ORDER)    | :TQ10001 |      0 |    918K|   308  (14)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   3 |    SORT ORDER BY        |          |      0 |    918K|   308  (14)|      0 |00:00:00.01 |       0 |      0 |    83M|  3142K|   37M (0)|
|   4 |     PX RECEIVE          |          |      0 |    918K|   277   (4)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   5 |      PX SEND RANGE      | :TQ10000 |      0 |    918K|   277   (4)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   6 |       PX BLOCK ITERATOR |          |      0 |    918K|   277   (4)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|*  7 |        TABLE ACCESS FULL| SALES    |      0 |    918K|   277   (4)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   7 - access(:Z>=:Z AND :Z<=:Z)

Note
-----
   - Degree of Parallelism is 2 because of hint 

Notice that the execution plan claims that the query completed in 0.70 seconds, that the calculated cost of the execution plan is (still) 308, that 28 blocks were read from disk, and 116 consistent gets were performed.

Here are the autotrace statistics for the serial execution:

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1718  consistent gets
       1647  physical reads
          0  redo size
   22116448  bytes sent via SQL*Net to client
    1102982  bytes received via SQL*Net from client
      61258  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
     918843  rows processed 

The DBMS_XPLAN generated execution plan for the serial execution plan follows:

SQL_ID  8k6bdqr09xc8u, child number 0
-------------------------------------
SELECT /*+ Q2 GATHER_PLAN_STATISTICS */ S.PROD_ID, S.CUST_ID, S.TIME_ID
FROM SH.SALES S ORDER BY S.AMOUNT_SOLD DESC

Plan hash value: 3803407550

-----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       |      1 |        |  6637 (100)|    918K|00:00:00.93 |    1718 |   1647 |       |       |          |
|   1 |  SORT ORDER BY       |       |      1 |    918K|  6637   (2)|    918K|00:00:00.93 |    1718 |   1647 |    42M|  2308K|   37M (0)|
|   2 |   PARTITION RANGE ALL|       |      1 |    918K|   499   (4)|    918K|00:00:00.31 |    1718 |   1647 |       |       |          |
|   3 |    TABLE ACCESS FULL | SALES |     28 |    918K|   499   (4)|    918K|00:00:00.22 |    1718 |   1647 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------- 

Notice that the execution plan claims that the query completed in 0.93 seconds, that the calculated cost of the execution plan is (still) 6,637, that 1,647 blocks were read from disk, and 1,718 consistent gets were performed.

The third challenge is to describe why DBMS_XPLAN claims that the parallel execution completed roughly 32.9% faster than the serial execution, when the timing output in SQL*Plus indicated that the reverse was true.  Bonus: Why do the Buffers and Reads statistics in the top row of the execution plan for the serial execution plan exactly match the autotrace generated consistent gets and physical reads statistics, yet the same is not true for the execution plan for the parallel execution?  Double Bonus: the execution plan claims that the query completed in 0.93 seconds, yet the timing information in SQL*Plus indicated that the query required an additional 7.55 seconds, why is there so much difference between the reported times (keep in mind that all testing was performed on the server, and the output was discarded without formatting and without displaying on screen)?

If cost is time, and time is money, what is the exchange rate for parallel execution?  ;-)

I have not fully worked the answers to the above challenge questions, and I will wait a couple of days before providing any feedback regarding proposed answers supplied by readers.  I strongly suspect that some readers know without a doubt the answers to all of the above questions.





Different Execution Plans when Converting SQL from SELECT to UPDATE … IN SELECT, ROWNUM Related Bug in 11.2.0.2

28 06 2012

June 28, 2012 (Modified June 28, 2012)

Sometimes it is possible to build a very effective test case to reproduce a particular problem.  Sometimes the test case drifts a bit offtrack, in the process revealing other information that is not directly related to the original problem that the test case attempted to simulate.  You will see several examples of test cases scripts used in various articles on this blog, including one that attempts to describe how to build useful test cases.  It is not uncommon to see test cases used to demonstrate various types of behavior, and there are several well known people in the Oracle Database community that use test cases to not only demonstrate problems, but also to teach methods of avoiding those problems.

The FAQ (Frequently Asked Questions) for the SQL and PL/SQL OTN forum includes links to two OTN threads that everyone posting to the forum about performance problems should read carefully:

When your query takes too long…
How to post a SQL statement tuning request

A handful of the good test cases have been posted to the OTN forums over the last couple of years that have then sparked an interesting article on this blog.  Take, for example, this OTN thread that provided a test case script to show that a poor execution plan was generated by the Oracle Database optimizer when ROWNUM was included in the WHERE clause.  Prior to Oracle Database 11.2.0.1, the cardinality calculation for steps in the execution plan that could not possibly be short-circuited early (such as a hash join with a subsequent ORDER BY) were affected by the ROWNUM predicate in the WHERE clause (of a parent query block).  That test case resulted in at least one article on this blog, which showed that with a bit of modification to the SQL statement, that it was possible to use the ROW_NUMBER analytic function as a replacement for ROWNUM, thus avoiding the automatic switch to a FIRST_ROWS(n) optimizer mode for the SQL statement.  This particular problem was determined to be a bug, and corrected with the release of Oracle Database 11.2.0.1.

Fast forward two and a half years, and we see another interesting, and oddly related test case in a thread on the OTN forum.  The OP (original poster) in the OTN forum thread generated the test case, posting his results from Oracle Database 10.2.0.5 (Standard Edition), while I posted my observed results from Oracle Database 11.2.0.2 in an attempt to find a more efficient method for updating rows that match specific criteria (other people helped also, possibly executing the test case script in other Oracle Database release versions).

What do we learn from the OTN test case script?  Here is a start:

  • When hinting a SQL statement to generate an expected execution plan, it is important to be as specific as possible with the hints, without boxing the SQL statement into a corner as the data volume increases in the various tables accessed by the SQL statement.  The hints also must appear in the correct section of a complex SQL statement with one or more inline views or subqueries.
  • If you use ROWNUM in the WHERE clause of a SQL statement, and then convert that SELECT statement to a UPDATE tablex WHERE coly IN (SELECT…) statement, you may find that the execution plan for the SELECT portion of the UPDATE statement changes dramatically from what was seen when just the SELECT statement was executed.  With Oracle Database 11.2.0.2, you may find that the first execution is efficient, and on the second execution find that cardinality feedback triggered a new hard parse of the SQL statement, resulting in a significantly less efficient execution plan (or possibly significantly more efficient execution plan).
  • AUTOTRACE in SQL*Plus lies about the execution plan sometimes, such as when cardinality feedback triggers the generation of a new execution plan.
  • Using a UNION ALL in an inline view will likely not permit the Oracle runtime engine to short-circuit an operation in the inline view when a ROWNUM condition is present in the parent SQL statement, even if the query optimizer’s generated execution plan indicates that this short-circuit will happen.  If possible, rewrite the SQL statement to avoid the UNION ALL operation, if both sections of the UNION ALL are accessing the same tables.
  • The GATHER_PLAN_STATISTICS hint, when added to a SQL statement, permits the use of DBMS_XPLAN.DISPLAY_CURSOR with the ALLSTATS LAST format parameter.  An execution plan generated with that format parameter will indicate whether or not short-circuiting of steps in an execution plan took place.  This short-circuiting will be indicated in the A-Rows column, the Starts column, and/or the Predicate Information section of the execution plan.
  • Within an inline view, an index-driven nested loop join that permits the elimination of an ORDER BY clause can be short-circuited by a ROWNUM condition in the parent portion of the SQL statement, while the same is not true for hash or sort-merge joins.
  • The ROWNUM cardinality calculation bug is still present in Oracle Database 11.2.0.2 if the inline view contains a UNION ALL clause – this bug is most apparent when cardinality feedback triggers the generation of a new execution plan on the second execution of the SQL statement.
  • In Oracle Database 11.2.0.2, query blocks in a SQL statement that cannot be short-circuited by a parent query block’s ROWNUM predicate are still optimized with an automatic FIRST_ROWS(n) optimizer mode (where n is the number associated with the parent operation’s ROWNUM predicate).  Through an apparent bug in the query optimizer, this automatic optimization may cause odd cost calculation problems, such as dropping the cost of a full table scan from 35.01 to 2.02 (with the cost of the corresponding hash join dropping from 56.76 to just 23.83); at the same time, due to cardinality feedback, the cost of an efficient index access path with a nested loops join (that may be short-circuited by the runtime engine) at the same point in the execution plan may increase from a cost of 41.32 to 2947.89.  As a result of the costing change, the nested loop join with index access path is likely to be replaced with a hash join and full table scan.

What else may we learn from the latest OTN test case thread?

Late Addition to the Article (June 28, 2012)

A side-by-side comparison of a portion of the 10053 trace file (showing the possible bug related to ROWNUM and cardinality feedback) that was generated by the following script (using the OP’s sample data):

DROP INDEX IND_DTL_TEST;

SET AUTOTRACE OFF
SET LINESIZE 140
SET PAGESIZE 1000

ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET TRACEFILE_IDENTIFIER='TESTING 1';

select /*+ GATHER_PLAN_STATISTICS */
  dtlid
from
  (select
     dtlid
   from
     (select
        dtlid,
        process_date
      from
        dtl
      where
        hdrid is null
        and process_date < (sysdate + 30)
        and process_ind = 'NEW'
      UNION ALL
      select
        dtl.dtlid,
        dtl.process_date
      from
        dtl,
        hdr
      where
        dtl.hdrid = hdr.hdrid
        and dtl.process_date < (sysdate + 30)
        and dtl.process_ind = 'NEW'
        and hdr_ind in (0, 2))
   order by
     dtlid,
     process_date)
where
  rownum <= 10;

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

ALTER SESSION SET TRACEFILE_IDENTIFIER='TESTING 2';

select /*+ GATHER_PLAN_STATISTICS */
  dtlid
from
  (select
     dtlid
   from
     (select
        dtlid,
        process_date
      from
        dtl
      where
        hdrid is null
        and process_date < (sysdate + 30)
        and process_ind = 'NEW'
      UNION ALL
      select
        dtl.dtlid,
        dtl.process_date
      from
        dtl,
        hdr
      where
        dtl.hdrid = hdr.hdrid
        and dtl.process_date < (sysdate + 30)
        and dtl.process_ind = 'NEW'
        and hdr_ind in (0, 2))
   order by
     dtlid,
     process_date)
where
  rownum <= 10;

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

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

The generated execution plan, before cardinality feedback:

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  4dwv2ktktv1ck, child number 1
-------------------------------------
select /*+ GATHER_PLAN_STATISTICS */   dtlid from   (select      dtlid
  from      (select         dtlid,         process_date       from
   dtl       where         hdrid is null         and process_date <
(sysdate + 30)         and process_ind = 'NEW'       UNION ALL
select         dtl.dtlid,         dtl.process_date       from
dtl,         hdr       where         dtl.hdrid = hdr.hdrid         and
dtl.process_date < (sysdate + 30)         and dtl.process_ind = 'NEW'
      and hdr_ind in (0, 2))    order by      dtlid,      process_date)
where   rownum <= 10

Plan hash value: 2201656677

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |          |      1 |        |     10 |00:00:00.05 |   31500 |       |       |          |
|*  1 |  COUNT STOPKEY                     |          |      1 |        |     10 |00:00:00.05 |   31500 |       |       |          |
|   2 |   VIEW                             |          |      1 |     22 |     10 |00:00:00.05 |   31500 |       |       |          |
|*  3 |    SORT ORDER BY STOPKEY           |          |      1 |     22 |     10 |00:00:00.05 |   31500 |  2048 |  2048 | 2048  (0)|
|   4 |     VIEW                           |          |      1 |     22 |   1367 |00:00:00.04 |   31500 |       |       |          |
|   5 |      UNION-ALL                     |          |      1 |        |   1367 |00:00:00.04 |   31500 |       |       |          |
|*  6 |       TABLE ACCESS FULL            | DTL      |      1 |     11 |    160 |00:00:00.01 |    1117 |       |       |          |
|   7 |       NESTED LOOPS                 |          |      1 |        |   1207 |00:00:00.07 |   30383 |       |       |          |
|   8 |        NESTED LOOPS                |          |      1 |     11 |   2838 |00:00:00.04 |   27566 |       |       |          |
|   9 |         TABLE ACCESS BY INDEX ROWID| DTL      |      1 |     32 |  15034 |00:00:00.02 |   15068 |       |       |          |
|* 10 |          INDEX RANGE SCAN          | DTL_IDX1 |      1 |        |  15034 |00:00:00.01 |      56 |       |       |          |
|* 11 |         INDEX UNIQUE SCAN          | HDR_PK   |  15034 |      1 |   2838 |00:00:00.01 |   12498 |       |       |          |
|* 12 |        TABLE ACCESS BY INDEX ROWID | HDR      |   2838 |      1 |   1207 |00:00:00.01 |    2817 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=10)
   3 - filter(ROWNUM<=10)
   6 - filter(("HDRID" IS NULL AND "PROCESS_IND"='NEW' AND "PROCESS_DATE"<SYSDATE@!+30))
  10 - access("DTL"."PROCESS_IND"='NEW' AND "DTL"."PROCESS_DATE"<SYSDATE@!+30)
  11 - access("DTL"."HDRID"="HDR"."HDRID")
  12 - filter(("HDR_IND"=0 OR "HDR_IND"=2)) 

After cardinality feedback:

SQL_ID  4dwv2ktktv1ck, child number 2
-------------------------------------
select /*+ GATHER_PLAN_STATISTICS */   dtlid from   (select      dtlid
  from      (select         dtlid,         process_date       from
   dtl       where         hdrid is null         and process_date <
(sysdate + 30)         and process_ind = 'NEW'       UNION ALL
select         dtl.dtlid,         dtl.process_date       from
dtl,         hdr       where         dtl.hdrid = hdr.hdrid         and
dtl.process_date < (sysdate + 30)         and dtl.process_ind = 'NEW'
      and hdr_ind in (0, 2))    order by      dtlid,      process_date)
where   rownum <= 10

Plan hash value: 986254152

---------------------------------------------------------------------------------------------------------------------
| Id  | Operation               | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |      |      1 |        |     10 |00:00:00.01 |    2437 |       |       |          |
|*  1 |  COUNT STOPKEY          |      |      1 |        |     10 |00:00:00.01 |    2437 |       |       |          |
|   2 |   VIEW                  |      |      1 |   2104 |     10 |00:00:00.01 |    2437 |       |       |          |
|*  3 |    SORT ORDER BY STOPKEY|      |      1 |   2104 |     10 |00:00:00.01 |    2437 |  2048 |  2048 | 2048  (0)|
|   4 |     VIEW                |      |      1 |   2104 |   1367 |00:00:00.01 |    2437 |       |       |          |
|   5 |      UNION-ALL          |      |      1 |        |   1367 |00:00:00.01 |    2437 |       |       |          |
|*  6 |       TABLE ACCESS FULL | DTL  |      1 |    160 |    160 |00:00:00.01 |    1117 |       |       |          |
|*  7 |       HASH JOIN         |      |      1 |   1944 |   1207 |00:00:00.01 |    1320 |  1517K|  1517K| 1398K (0)|
|*  8 |        TABLE ACCESS FULL| HDR  |      1 |   6667 |   4285 |00:00:00.01 |     203 |       |       |          |
|*  9 |        TABLE ACCESS FULL| DTL  |      1 |  15034 |  15034 |00:00:00.01 |    1117 |       |       |          |
---------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=10)
   3 - filter(ROWNUM<=10)
   6 - filter(("HDRID" IS NULL AND "PROCESS_IND"='NEW' AND "PROCESS_DATE"<SYSDATE@!+30))
   7 - access("DTL"."HDRID"="HDR"."HDRID")
   8 - filter(("HDR_IND"=0 OR "HDR_IND"=2))
   9 - filter(("DTL"."PROCESS_IND"='NEW' AND "DTL"."PROCESS_DATE"<SYSDATE@!+30))

Note
-----
   - cardinality feedback used for this statement 

In the above example, cardinality feedback helped to reduce the execution time.  Notice in the first plan that the E-Rows column shows that the ROWNUM predicate was pushed too far into the inline view’s cardinality calculations.  So, cardinality feedback helped in the above example.  Now, let’s look at what happens to my optimized version of the SQL statement that removes the UNION ALL:

select
  dtlid
from
  (select
     dtlid
   from
     (select /*+ INDEX(DTL) INDEX(HRD) USE_NL(DTL HDR) */
        dtl.dtlid,
        dtl.process_date
      from
        dtl,
        hdr
      where
        dtl.hdrid = hdr.hdrid(+)
        and dtl.process_date < (sysdate + 30)
        and dtl.process_ind = 'NEW'
        and (
            (hdr_ind in (0, 2) and dtl.hdrid IS NOT NULL)
            OR (dtl.hdrid IS NULL)))
   order by
     dtlid,
     process_date) 

The execution plan before cardinality feedback:

SQL_ID  5d8128vjhm1j0, child number 0
-------------------------------------
select /*+ GATHER_PLAN_STATISTICS */   dtlid from   (select      dtlid
  from      (select         dtl.dtlid,         dtl.process_date
from         dtl,         hdr       where         dtl.hdrid =
hdr.hdrid(+)         and dtl.process_date < (sysdate + 30)         and
dtl.process_ind = 'NEW'         and (             (hdr_ind in (0, 2)
and dtl.hdrid IS NOT NULL)             OR (dtl.hdrid IS NULL)))
order by      dtlid,      process_date) where   rownum <= 10

Plan hash value: 1187173211

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |     10 |00:00:00.01 |      80 |
|*  1 |  COUNT STOPKEY                  |              |      1 |        |     10 |00:00:00.01 |      80 |
|   2 |   VIEW                          |              |      1 |     11 |     10 |00:00:00.01 |      80 |
|*  3 |    FILTER                       |              |      1 |        |     10 |00:00:00.01 |      80 |
|   4 |     NESTED LOOPS OUTER          |              |      1 |     11 |     19 |00:00:00.01 |      80 |
|   5 |      TABLE ACCESS BY INDEX ROWID| DTL          |      1 |  19635 |     19 |00:00:00.01 |      52 |
|*  6 |       INDEX FULL SCAN           | IND_DTL_TEST |      1 |     16 |     19 |00:00:00.01 |      49 |
|   7 |      TABLE ACCESS BY INDEX ROWID| HDR          |     19 |      1 |     18 |00:00:00.01 |      28 |
|*  8 |       INDEX UNIQUE SCAN         | HDR_PK       |     19 |      1 |     18 |00:00:00.01 |      10 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=10)
   3 - filter(((INTERNAL_FUNCTION("HDR_IND") AND "DTL"."HDRID" IS NOT NULL) OR "DTL"."HDRID" IS
              NULL))
   6 - access("DTL"."PROCESS_IND"='NEW' AND "DTL"."PROCESS_DATE"<SYSDATE@!+30)
       filter(("DTL"."PROCESS_IND"='NEW' AND "DTL"."PROCESS_DATE"<SYSDATE@!+30))
   8 - access("DTL"."HDRID"="HDR"."HDRID") 

The execution plan after cardinality feedback:

SQL_ID  5d8128vjhm1j0, child number 1
-------------------------------------
select /*+ GATHER_PLAN_STATISTICS */   dtlid from   (select      dtlid
  from      (select         dtl.dtlid,         dtl.process_date
from         dtl,         hdr       where         dtl.hdrid =
hdr.hdrid(+)         and dtl.process_date < (sysdate + 30)         and
dtl.process_ind = 'NEW'         and (             (hdr_ind in (0, 2)
and dtl.hdrid IS NOT NULL)             OR (dtl.hdrid IS NULL)))
order by      dtlid,      process_date) where   rownum <= 10

Plan hash value: 672193791

--------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |        |      1 |        |     10 |00:00:00.02 |    5315 |       |       |          |
|*  1 |  COUNT STOPKEY                   |        |      1 |        |     10 |00:00:00.02 |    5315 |       |       |          |
|   2 |   VIEW                           |        |      1 |      9 |     10 |00:00:00.02 |    5315 |       |       |          |
|*  3 |    SORT ORDER BY STOPKEY         |        |      1 |      9 |     10 |00:00:00.02 |    5315 |  2048 |  2048 | 2048  (0)|
|*  4 |     FILTER                       |        |      1 |        |   1374 |00:00:00.02 |    5315 |       |       |          |
|   5 |      NESTED LOOPS OUTER          |        |      1 |      9 |  15115 |00:00:00.02 |    5315 |       |       |          |
|*  6 |       TABLE ACCESS FULL          | DTL    |      1 |     19 |  15115 |00:00:00.01 |    1117 |       |       |          |
|   7 |       TABLE ACCESS BY INDEX ROWID| HDR    |  15115 |      1 |   2853 |00:00:00.01 |    4198 |       |       |          |
|*  8 |        INDEX UNIQUE SCAN         | HDR_PK |  15115 |      1 |   2853 |00:00:00.01 |    1345 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=10)
   3 - filter(ROWNUM<=10)
   4 - filter(((INTERNAL_FUNCTION("HDR_IND") AND "DTL"."HDRID" IS NOT NULL) OR "DTL"."HDRID" IS NULL))
   6 - filter(("DTL"."PROCESS_IND"='NEW' AND "DTL"."PROCESS_DATE"<SYSDATE@!+30))
   8 - access("DTL"."HDRID"="HDR"."HDRID")

Note
-----
   - cardinality feedback used for this statement 

In the above, notice that the reported A-Time increased from 0.01 seconds (the actual time could be must faster than that) to 0.02 seconds.  The number of consistent gets also increased from 80 to 5,315.  Cardinality feedback will NOT automatically change the execution plan back to the more efficient execution plan during later executions of the SQL statement.





Why is a Full Table Scan Selected – Will the Execution Plan Provide a Clue?

20 06 2012

June 20, 2012

I have not had much time to respond in OTN threads recently, although I do still occasionally read threads on the forum.  I was a little surprised by one of the late responses in one of the recent threads, where one of the responders suggested actually testing the problem with the assistance of execution plans.  Additionally, that responder suggested that the earlier responses missed the target.  Ouch!

The OP did not provide DDL to create the table or indexes, or DML to populate the table.  The SQL statement provided by the OP was apparently looking for rows where the VARCHAR2 column A was blank (as in containing a zero length string).  If an index exists on column A, why would the optimizer select to perform a full table scan when attempting to return all rows with a zero length string in column A?  (Raise your hand if you know the answer.)

Let’s create a test table with four indexes so that we are able to test some of the theories (or possible causes) that were proposed in the thread:

DROP TABLE T1 PURGE;

CREATE TABLE T1 AS 
SELECT
  ROWNUM C1,
  MOD(ROWNUM,10) C2,
  TRUNC(ROWNUM/10000) C3,
  RPAD(TO_CHAR(ROWNUM),6,'A') C4,
  LPAD('A',200,'A') C5
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

ALTER TABLE T1 MODIFY (
  C1 NOT NULL,
  C2 NOT NULL,
  C3 NOT NULL);

CREATE INDEX IND_T1_C1 ON T1(C1);
CREATE INDEX IND_T1_C2 ON T1(C2);
CREATE INDEX IND_T1_C3 ON T1(C3);
CREATE INDEX IND_T1_C4 ON T1(C4);

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

SET LINESIZE 140
SET PAGESIZE 1000 

The above script creates a table with 100,000 rows, with the first 3 columns declared as NOT NULL.  Column C1 contains the numbers 1 through 100,000.  Column C2 contains the numbers 0 through 9 in a repeating pattern.  Column C3 contains the numbers 0 through 10 with most of the rows containing the same value likely closely bunched together (a single row contains the number 10).  Column C4 is a simple VARCHAR2 column that is the number 1 through 100,000 padded to six characters using the letter A.  The statistics for the table and indexes were collected with a 100% sampling percentage.

Using the test table created by the above script, we might simulate the OP’s SQL statement using the following.  One of the last responders in the OTN thread recommended looking at the execution plan, so we will retrieve that also:

SELECT
  *
FROM
  T1
WHERE
  C4='';

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

Unfortunately, the two single quotes () in the SQL statement are not interpretted as a test for a zero length string as happens on other DB platforms, and as the OP likely intended (see this AskTom thread).  The Oracle Database 11.2.0.2 output of the above follows:

no rows selected

SQL>

SQL_ID  5tc2j4q52493b, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   C4=''

Plan hash value: 3332582666

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |     1 (100)|          |
|*  1 |  FILTER            |      |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T1   |   100K|    20M|   252   (1)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

So, the Predicate Information section shows NULL IS NOT NULL, which never has a result of TRUE.  Notice that the full table scan has a cost of 252, yet plan row 0, which is a grandparent of row 2, has a cost of 1 (costs for parent operations are supposed to include the calculated cost of child operations plus the calculated cost of the work performed at the parent operation).  (Raise your hand if you know the answer why plan row 0 has a cost of 1 when plan row 2 has a cost of 252.)  We will have to come back to this execution plan oddity later.

For a SQL statement like the following, which should return one row, you would expect the index on column C1 to be used:

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C1=9;

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

Here is the output of the above:

        C1         C2         C3 C4     C5
---------- ---------- ---------- ------ ----------
         9          9          0 9AAAAA AAAAAAAAAA

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

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------
SQL_ID  90d7zdbavdpuu, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C1=9

Plan hash value: 683303157

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |     1 |   219 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C1 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1"=9) 

So, an index range scan was performed to retrieve the one row from table T1.  (Raise your hand if you know the answer why an index range scan operation was selected when every value in column C1 is unique and an equality predicate was used in the WHERE clause.)

For the following SQL statement, where an index on column C2 would likely have a large clustering factor value, should an index be used to retrieve 10% of the rows from the table?

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C2=9;

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

Here is a portion of the output from the above SQL statement:

...
     99969          9          9 99969A AAAAAAAAAA
     99979          9          9 99979A AAAAAAAAAA
     99989          9          9 99989A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
SQL_ID  459zvkh9p725k, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C2=9

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   252 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   | 10000 |  2138K|   252   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=9) 

The optimizer selected to use a full table scan in order to retrieve 10% of the rows from the table.  (Raise your hand if you know the answer why a full table scan was selected.)

A final SQL statement that also retrieves 10% of the rows from the table, this time using column C3:

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C3=9;

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

For the above SQL statement, would you expect the optimizer to select the use of an index range scan operation, or a full table scan operation?  Here is the output that I received:

...
     99996          6          9 99996A AAAAAAAAAA
     99997          7          9 99997A AAAAAAAAAA
     99998          8          9 99998A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
SQL_ID  4c1s2vujtc1ff, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C3=9

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   252 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |  9091 |  1944K|   252   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C3"=9) 

So, once again the optimizer selected to use a full table scan to facilitate the retrieval of 10% of the rows from the table.  But why, the clustering factor should be reasonably low.  (Raise your hand if you know the answer why a full table scan was selected.)

But wait… the optimizer from another 11.2.0.2 database instance decided differently:

...
     99996          6          9 99996A AAAAAAAAAA
     99997          7          9 99997A AAAAAAAAAA
     99998          8          9 99998A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------
SQL_ID  4c1s2vujtc1ff, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C3=9

Plan hash value: 1220227203

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   304 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |  9091 |  1944K|   304   (1)| 00:00:02 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C3 |  9091 |       |    18   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C3"=9) 

Why did the optimizer in one of the 11.2.0.2 database instances select to use a full table scan operation, while the optimizer in the other database instance selected to use an index range scan operation?  (Raise your hand if you know the answer why there is a difference between the two execution plan results.)

If we take another look at the execution plan for the SQL statement that simulates the problem experienced by the OP, I wonder if we are able to determine why the parent operation has a lower calculated cost than its child (or grandchild’s) calculated cost?

SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C4='';

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

Let’s take a look at the output of the above:

no rows selected

SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------
SQL_ID  63yz0tn58sz4v, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C4=''

Plan hash value: 3332582666

----------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |     1 (100)|      0 |00:00:00.01 |
|*  1 |  FILTER            |      |      1 |        |            |      0 |00:00:00.01 |
|   2 |   TABLE ACCESS FULL| T1   |      0 |    100K|   252   (1)|      0 |00:00:00.01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

Do you see it?  Does it matter if a full table scan of table T1 was selected by the optimizer?   (Raise your hand if you know the answer.)

What if we force an index access path:

SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */
  *
FROM
  T1
WHERE
  C4='';

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

Here is the output of the above:

no rows selected

SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------
SQL_ID  06ucccd8j8ss0, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */   * FROM   T1 WHERE
C4=''

Plan hash value: 1158503954

-------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |      1 |        |     1 (100)|      0 |00:00:00.01 |
|*  1 |  FILTER                      |           |      1 |        |            |      0 |00:00:00.01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1        |      0 |    100K|  3323   (1)|      0 |00:00:00.01 |
|   3 |    INDEX FULL SCAN           | IND_T1_C3 |      0 |    100K|   196   (1)|      0 |00:00:00.01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

Is the above execution plan even legal because the SQL statement is essentially looking for NULL values?  (Raise your hand if you know the answer.)

—-

OK, put down your hand – the other people in the office are probably laughing at your hand-waving by now.  ;-)

I wonder if the OP now understands the problem with his SQL statement?

—–

Late Addition June 20, 2012:

Recall that the optimizer selected that a full table scan should be used for the initial SELECT statement.  Part 2 of a previous blog article on this blog pointed to an article on another blog, asking whether or not a couple of statements made on the other blog were true regarding whether or not NULL values were ever stored in a B*tree index structure.  One of my previous articles seemed to offer a counter-point, that in fact it is possible for a B*tree index to contain NULL values in certain situations.

What might happen if we swap in a bind variable in place of the literal in the initial SELECT statement?  If we set the bind variable to have a value of (the same value as the literal), will the optimizer select to use a full table scan operation or an index range scan operation?  Will the STARTS column in the execution plan contain 0 for one or more of the rows in the execution plan?  Let’s test:

VARIABLE V1 VARCHAR2
EXEC :V1:=''
 
SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C4= :V1;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST')); 

Here is the output:

no rows selected
 
SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------
SQL_ID  c4faj4cgbdrw1, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C4= :V1
 
Plan hash value: 7035821
 
------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|      0 |00:00:00.01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |      1 |      1 |     2   (0)|      0 |00:00:00.01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C4 |      1 |      1 |     1   (0)|      0 |00:00:00.01 |
------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C4"=:V1)

Notice that none of the rows in the execution plan have a STARTS value of 0, and that filter(NULL IS NOT NULL) does not appear in the Predicate Information section of the execution plan as had happened when we used a literal with the same value as the bind variable.  So, if the OP would like to see an index access path in the execution plan, perhaps he should use bind variables rather than literals?  Is the above execution plan more efficient or less efficient than the execution plan with the full table scan operation that was seen when a literal was passed in the SQL statement?

Let’s insert a row into table T4 with our bind variable value being placed in column C4:

INSERT INTO T1 VALUES(
  -1,
  -1,
  -1,
  :V1,
  'A');
 
COMMIT;
 
SELECT /*+ GATHER_PLAN_STATISTICS  FIND_ME */
  *
FROM
  T1
WHERE
  C4= :V1;
  
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));

Will a row be returned?  Will the execution plan change?  Here is the output for the above script:

no rows selected
 
SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------
SQL_ID  csmkq5csd6f0a, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS  FIND_ME */   * FROM   T1 WHERE   C4=
:V1
 
Plan hash value: 7035821
 
------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|      0 |00:00:00.01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |      1 |      1 |     2   (0)|      0 |00:00:00.01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C4 |      1 |      1 |     1   (0)|      0 |00:00:00.01 |
------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C4"=:V1)

No rows selected, even though a row was just inserted into the table with the same value  as what is in bind variable V1.  Let’s DUMP the values of a couple of columns from the row that was just inserted:

COLUMN DUMP_C1 FORMAT A25
COLUMN DUMP_C4 FORMAT A25
 
SELECT
  C1,
  DUMP(C1) DUMP_C1,
  C4,
  DUMP(C4) DUMP_C4
FROM
  T1
WHERE
  C1=-1;
 
        C1 DUMP_C1                   C4     DUMP_C4
---------- ------------------------- ------ -------------------------
        -1 Typ=2 Len=3: 62,100,102          NULL

The above output shows that column C4 of this row contains a NULL value.  I suggest that it might not matter whether or not the execution plan shows an index access path or a full table scan for this SQL statement – if the SQL statement is answering a different question than what the OP expects, then it does not matter whether or not the SQL statement executes efficiently.

However, as a bonus we were able to see the optimizer using an index access path to check for a NULL value.





Execution Plan Changes when the OPTIMIZER_FEATURES_ENABLED Parameter is Changed, But Why?

30 05 2012

May 30, 2012

A question appeared on the OTN Database forums yesterday that has yet to receive an answer.  The question was essentially, why did the execution plan change when the OPTIMIZER_FEATURES_ENABLED parameter was adjusted from 11.2.0.2 to 11.1.0.7, and why did the execution performance improve as a result of making the change?  A DBMS_XPLAN generated execution plan where TYPICAL +OUTLINE were apparently specified for the format parameters was provided for the execution with the OPTIMIZER_FEATURES_ENABLED parameter set to 11.2.0.2, while the format parameter was apparently set to ALLSTATS LAST for the 11.1.0.7 test execution.  Why did the performance improve when the optimizer’s parameter was modified?

We do not have access to the SQL statement, but we do have a few clues.  Take a look at the Predicate Information section, you will see the following:

1 - filter(ROWNUM<=1000)

So, ROWNUM<=1000 was specified in the SQL statement.  As mentioned in one of my other articles, there was a bug in the optimizer’s code prior to Oracle Database 11.2.0.1 related to the appearance of ROWNUM in the WHERE clause.  Would changing the  OPTIMIZER_FEATURES_ENABLED parameter to 11.1.0.7 reinstate the bug (this would not happen based on testing that I performed some time ago)?  The OP stated that the OPTIMIZER_MODE parameter is set to FIRST_ROWS_10, could specifying ROWNUM<=1000 cause the optimizer to behave as if FIRST_ROWS_1000 was set for the optimizer mode, behaving differently depending on the value of the OPTIMIZER_FEATURES_ENABLED parameter?

What other clues did the OP provide for potential readers of the OTN thread?  Let’s take a look at a portion of the outline sections supplied with the execution plans to see if there are any clues.  With OPTIMIZER_FEATURES_ENABLED set to 11.2.0.2:

OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
DB_VERSION('11.2.0.2')
OPT_PARAM('_push_join_union_view' 'false')
OPT_PARAM('_optim_peek_user_binds' 'false')
OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
OPT_PARAM('optimizer_index_cost_adj' 10)
OPT_PARAM('optimizer_index_caching' 80)
FIRST_ROWS(10)

With OPTIMIZER_FEATURES_ENABLED set to 11.1.0.7:

OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
DB_VERSION('11.2.0.2')
OPT_PARAM('_optim_peek_user_binds' 'false')
OPT_PARAM('optimizer_index_cost_adj' 10)
OPT_PARAM('optimizer_index_caching' 80)
FIRST_ROWS(10)

Well, that is a bit interesting.  The OPTIMIZER_INDEX_COST_ADJ parameter was set to 10 in both cases, and the OPTIMIZER_INDEX_CACHING parameter was set to 80 in both cases – could the change in the execution plan be caused by a cost rounding error that is somehow slightly different when the OPTIMIZER_FEATURES_ENABLED parameter is changed?

While we are looking at the outline sections, notice that in the test with the OPTIMIZER_FEATURES_ENABLED parameter set at 11.2.0.2 that the _OPTIM_PEEK_USER_BINDS, _PUSH_JOIN_UNION_VIEW, and _GBY_HASH_AGGREGATION_ENABLED hidden parameters are all set at the non-default value of FALSE, while the test with the OPTIMIZER_FEATURES_ENABLED parameter set at 11.1.0.7 only shows that the _OPTIM_PEEK_USER_BINDS parameter is set to the non-default value of FALSE – could that difference cause of the execution plan change, and might those two hidden parameters magically change back to their default values when adjusting the OPTIMIZER_FEATURES_ENABLED parameter?

The OP did not supply a test case script, so I will create a simple test case script just to see if those two hidden parameters might magically change back to their default values when the  OPTIMIZER_FEATURES_ENABLED parameter is adjusted.

DROP TABLE T1 PURGE;

CREATE TABLE T1 AS
SELECT
  ROWNUM C1,
  DECODE(ROWNUM,1,1,0) C2,
  LPAD('A',255,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE UNIQUE INDEX IND_T1_C1 ON T1(C1);
CREATE INDEX IND_T1_C2 ON T1(C2);

ALTER TABLE T1 MODIFY (C1 NOT NULL, C2 NOT NULL);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR ALL INDEXED COLUMNS SIZE 254') 

SET PAGESIZE 1000
SET LINESIZE 140

It appears that the OP had the following parameters set for the execution at 11.2.0.2:

ALTER SESSION SET "_push_join_union_view"=false;
ALTER SESSION SET "_optim_peek_user_binds"=false;
ALTER SESSION SET "_gby_hash_aggregation_enabled"=false;
ALTER SESSION SET optimizer_index_cost_adj=10;
ALTER SESSION SET optimizer_index_caching=80;
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_10;

Let’s try a test script (note that you may wish to change the event 10132 to 10053, because the output of the 10132 trace event seems to be a bit scrambled in Oracle Database 11.2.0.2):

ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='11.2.0.2';
ALTER SESSION SET TRACEFILE_IDENTIFIER='11.2.0.2 HIDDEN TEST';
ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000
  AND C2=2
  AND C1>=1;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'+OUTLINE'));

ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='11.1.0.7';
ALTER SESSION SET TRACEFILE_IDENTIFIER='11.1.0.7 HIDDEN TEST';

SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000
  AND C2=2
  AND C1>=1;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'+OUTLINE'));
ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT OFF';

Here is the output that I received for 11.2.0.2:

SQL> SELECT
  2    *
  3  FROM
  4    T1
  5  WHERE
  6    ROWNUM<=1000
  7    AND C2=2
  8    AND C1>=1;

no rows selected

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'+OUTLINE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------
SQL_ID  fb2ysnjkbq366, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   ROWNUM<=1000   AND C2=2   AND C1>=1

Plan hash value: 1016793414

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |     1 (100)|          |
|*  1 |  COUNT STOPKEY               |           |       |       |            |          |
|*  2 |   TABLE ACCESS BY INDEX ROWID| T1        |     1 |   136 |     1   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IND_T1_C2 |     1 |       |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('_push_join_union_view' 'false')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 10)
      OPT_PARAM('optimizer_index_caching' 80)
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C2"))
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=1000)
   2 - filter("C1">=1)
   3 - access("C2"=2) 

The output for 11.1.0.7:

SQL_ID  fb2ysnjkbq366, child number 1
-------------------------------------
SELECT   * FROM   T1 WHERE   ROWNUM<=1000   AND C2=2   AND C1>=1

Plan hash value: 1016793414

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |     1 (100)|          |
|*  1 |  COUNT STOPKEY               |           |       |       |            |          |
|*  2 |   TABLE ACCESS BY INDEX ROWID| T1        |     1 |   136 |     1   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IND_T1_C2 |     1 |       |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('_push_join_union_view' 'false')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 10)
      OPT_PARAM('optimizer_index_caching' 80)
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C2"))
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=1000)
   2 - filter("C1">=1)
   3 - access("C2"=2) 

How would you answer the OP?  Could it just be the case that most of the required database blocks were in the buffer cache on the second execution when the OPTIMIZER_FEATURES_ENABLED parameter was adjusted?  If nothing else, this OTN thread provides an excuse to think about possible causes and effects when insufficient information is provided.





TKPROF Elapsed Time Challenge – the Elapsed Time is Half of the Wait Event Time

20 05 2012

May 20, 2012

An interesting quirk was recently brought to my attention by Mich Talebzadeh.  He generated a 10046 trace at level 8 for a session, executed some SQL statements, disabled the trace, and then processed the resulting trace file with TKPROF.  His TKPROF output included the following:

UPDATE TESTWRITES SET PADDING1 = RPAD('y',4000,'y')
WHERE
OBJECT_ID = :B1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute  17293     21.62    1245.41    1064667    2411398    6280588     1000000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    17297     21.62    1245.41    1064667    2411398    6280588     1000000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 93     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  TESTWRITES (cr=214 pr=427 pw=0 time=0 us)
    100   INDEX UNIQUE SCAN TESTWRITES_PK (cr=110 pr=3 pw=0 time=0 us cost=2 size=4007 card=1)(object id 92380)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                   2160263        1.57       2304.22
  db file scattered read                      27769        0.26         99.78 

Mich noticed that the reported elapsed time, at 1,245.41 seconds, is less than the sum of the wait event times, at 2,400.00 seconds.  Typically, the sum of the wait events plus the CPU time should be equal to or slightly less than the elapsed time (assuming that parallel query is not used, and the CPU reporting granularity did not cause odd side effects, and the session’s process did not spend much time in the CPU run queue).  In this case, the elapsed time is about 51.9% of the wait event time for this SQL statement. 

How is this possible?  Mich stated the following:

“A comment has been it is due to using different clock granularities.”

Think about that for a minute – what could explain the odd inconsistency in the output?

I recall reading in the book “Optimizing Oracle Performance” about double-counting of statistics due to recursive database calls.  Page 92 of that book includes the following quote:

“In Oracle releases through at least Oracle9i Release 2, a database call’s c, e, p, cr, and cu statistics contain an aggregation of the resources consumed by the database call itself and its entire recursive progeny.”

Page 91 of the same book makes the following statement:

“The rule for determining the recursive relationships among database calls is simple:
A database call with dep=n + 1 is the recursive child of the first subsequent dep=n database call listed in the SQL trace data stream.”

Could it be the case that this particular issue with recursive calls was addressed in later releases of TKPROF?  Might that fix explain why the elapsed time is 51.9% of the wait event time?

The OP provided a partial test case script with a description of how the tables were created.  I reduced the size of the original source table from 1,700,000 rows to 60,000 rows, and reduced the secondary source table from 1,000,000 rows to 50,000 rows.  My test script follows (note that the line that builds the IND_T2_OBJ index is commented out – we will change that later):

DROP TABLE T1 PURGE;
DROP TABLE T2 PURGE;

CREATE TABLE T1 AS
SELECT
  *
FROM
  ALL_OBJECTS
WHERE
  ROWNUM<=60000;

ALTER TABLE T1 ADD (
  PADDING1 VARCHAR2(4000),
  PADDING2 VARCHAR2(4000));

CREATE TABLE T2 AS
SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=50000;

CREATE UNIQUE INDEX IND_T1_OBJ ON T1(OBJECT_ID);
--CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

ALTER SYSTEM FLUSH SHARED_POOL;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true, plan_stat=>'ALL_EXECUTIONS' );

DECLARE
        type ObjIdArray is table of T1.object_id%TYPE index by binary_integer;
        l_ids objIdArray;
        CURSOR c IS SELECT object_id FROM T1;
BEGIN
        OPEN c;
        LOOP
                BEGIN
                        FETCH c BULK COLLECT INTO l_ids LIMIT 100;

                        FORALL rs in 1 .. l_ids.COUNT
                                UPDATE T2
                                  SET PADDING1 =  RPAD('y',4000,'y')
                                WHERE object_id = l_ids(rs);
                        commit;
                        FORALL rs in 1 .. l_ids.COUNT
                                DELETE FROM T2
                                WHERE object_id = l_ids(rs);
                        commit;
                        FORALL rs in 1 .. l_ids.COUNT
                                INSERT INTO T2
                                SELECT * FROM T1 t WHERE t.object_id = l_ids(rs);
                        commit;
                        EXIT WHEN C%NOTFOUND;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN
                    NULL;
                  WHEN OTHERS THEN
                    DBMS_OUTPUT.PUT_LINE('Transaction failed');
                END;
        END LOOP;
        CLOSE c;
END;
/

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE;

That test case definitely contains calls in the trace file at a dep greater than zero.  As a matter of fact, the SQL statement of interest is at a dep of one, resulting in space management (and other calls) at a dep of two or greater:

PARSING IN CURSOR #397285536 len=66 dep=1 uid=64 oct=6 lid=64 tim=1879257875778 hv=3592437181 ad='3edea5858' sqlid='1ahnbczb20gdx'
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 
END OF STMT
PARSE #397285536:c=0,e=169,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1879257875778

I executed the test case script on 64 bit Windows with Oracle Database 11.2.0.2 with patch 5 installed.  I processed the resulting trace file with TKPROF from the 32 bit Windows Oracle 11.2.0.1 client with the ODBC update patch 10155837 installed.  My TKPROF output for the UPDATE statement showed the following:

SQL ID: 1ahnbczb20gdx
Plan Hash: 2722410703
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') 
WHERE
 OBJECT_ID = :B1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    600    197.38     197.60        452   50299237     426582       50000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      601    197.38     197.60        452   50299237     426582       50000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  T2 (cr=80409 pr=436 pw=0 time=357525 us)
       100        100        100   TABLE ACCESS FULL T2 (cr=80182 pr=420 pw=0 time=337295 us cost=116 size=16120 card=8)
         0          0          0  UPDATE  T2 (cr=83795 pr=0 pw=0 time=344133 us)
       100        100        100   TABLE ACCESS FULL T2 (cr=83598 pr=0 pw=0 time=332180 us cost=116 size=16120 card=8)
         0          0          0  UPDATE  T2 (cr=83790 pr=2 pw=0 time=303134 us)
       100        100        100   TABLE ACCESS FULL T2 (cr=83596 pr=0 pw=0 time=288815 us cost=116 size=16120 card=8)
         0          0          0  UPDATE  T2 (cr=83789 pr=2 pw=0 time=283738 us)
       100        100        100   TABLE ACCESS FULL T2 (cr=83595 pr=0 pw=0 time=271190 us cost=116 size=16120 card=8)
...
         0          0          0  UPDATE  T2 (cr=87900 pr=0 pw=0 time=375297 us)
         0          0          0   TABLE ACCESS FULL T2 (cr=87900 pr=0 pw=0 time=375015 us cost=116 size=16120 card=8)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        36        0.00          0.01
  db file scattered read                         31        0.00          0.01

I decided to compare the output of TKPROF with the output of my Hyper-Extended Oracle Performance Monitor program, which I know does not attempt to resolve parent and child recursive statistics:

Statement Depth 1 (Trigger Code)
Cursor 220   Ver 1   Parse at 0.254283 SQL_ID='1ahnbczb20gdx'  (TD Prev 0.000877)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000169|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs      600|CPU S  197.403668|CLOCK S  197.659011|ROWs    50000|PHY RD BLKs       774|CON RD BLKs (Mem)  50299674|CUR RD BLKs (Mem)    426582|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 25.08%  CLOCK S 25.01%
|               +++++||               +++++|
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1

       (Rows 0)   UPDATE  T2 (cr=80409 pr=436 pw=0 time=357525 us)
     (Rows 100)    TABLE ACCESS FULL T2 (cr=80182 pr=420 pw=0 time=337295 us cost=116 size=16120 card=8)

       (Rows 0)   UPDATE  T2 (cr=83795 pr=0 pw=0 time=344133 us)
     (Rows 100)    TABLE ACCESS FULL T2 (cr=83598 pr=0 pw=0 time=332180 us cost=116 size=16120 card=8)
       (Rows 0)   UPDATE  T2 (cr=83790 pr=2 pw=0 time=303134 us)
     (Rows 100)    TABLE ACCESS FULL T2 (cr=83596 pr=0 pw=0 time=288815 us cost=116 size=16120 card=8)
...

Notice that the TKPROF summary shows 0.059011 fewer elapsed seconds for this SQL statement, 0.023668 fewer CPU seconds, 322 fewer blocks read from disk, 437 fewer consistent gets, and the same number of current mode reads.  Why the differences?

My program wrote the wait event details for the UPDATE statement to an Excel spreadsheet.  Examination of the wait events indicated that there were 36 db file sequential read waits (thus 36 total blocks read from disk), and 31 db file scattered read waits (416 total blocks read from disk) – the wait event details support the statistics output by TKPROF.  So, maybe the double counting of recursive calls was fixed since the release of Oracle Database 9.2.  Nice!  But we are not done yet, we still do not have the index on table T2, as was described by the OP.

Locate in the script the following line:

--CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

Change that line by removing the at the start of the line, so that the line appears like this:

CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

Disconnect from the database, then reconnect (so that you will be assigned a different default trace filename).  Now, re-execute the script, and process the resulting trace file with TKPROF.  My TKPROF output for the UPDATE SQL statement looks like this:

SQL ID: 1ahnbczb20gdx
Plan Hash: 1751280057
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') 
WHERE
 OBJECT_ID = :B1 

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    190      1.35       1.42        348      52552     165435       19000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      191      1.35       1.42        348      52552     165435       19000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  T2 (cr=332 pr=30 pw=0 time=19223 us)
       100        100        100   INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=8 pw=0 time=1372 us cost=1 size=2015 card=1)(object id 103855)
         0          0          0  UPDATE  T2 (cr=288 pr=2 pw=0 time=8629 us)
       100        100        100   INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0
...
         0          0          0  UPDATE  T2 (cr=291 pr=0 pw=0 time=6051 us)
       100        100        100   INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=430 us cost=1 size=2015 card=1)(object id 103855)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file scattered read                         40        0.00          0.03
  db file sequential read                        32        0.00          0.01
  log file switch completion                      2        0.00          0.01

For the sake of comparison, I also processed the trace file using my Hyper-Extended Oracle Performance Monitor program.  This is my program’s output:

Statement Depth 1 (Trigger Code)
Cursor 910   Ver 1   Parse at 0.187068 SQL_ID='1ahnbczb20gdx'  (TD Prev 0.000996)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000162|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs      600|CPU S    3.603618|CLOCK S    3.683344|ROWs    50000|PHY RD BLKs       912|CON RD BLKs (Mem)    144826|CUR RD BLKs (Mem)    426496|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 16.91%  CLOCK S 15.45%
|                 +++||                 +++|
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1

       (Rows 0)   UPDATE  T2 (cr=332 pr=30 pw=0 time=19223 us)
     (Rows 100)    INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=8 pw=0 time=1372 us cost=1 size=2015 card=1)

       (Rows 0)   UPDATE  T2 (cr=288 pr=2 pw=0 time=8629 us)
     (Rows 100)    INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=430 us cost=1 size=2015 card=1)
...
       (Rows 0)   UPDATE  T2 (cr=105 pr=0 pw=0 time=193 us)
       (Rows 0)    INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=153 us cost=1 size=2015 card=1)

Notice that there is now a significant difference in the elapsed time at 2.263344 seconds difference, CPU seconds at a difference of 2.253618 seconds, and the number of blocks read from disk at a difference of 564 blocks.

Let’s take a look at the wait events that my program wrote to Excel.   Examination of the wait events indicated that there were 42 db file sequential read waits (thus 42 total blocks read from disk), and 107 db file scattered read waits (842 total blocks read from disk), for a grand total of 884 blocks read from disk that are associated with this UPDATE SQL statement.  This time, not only are the TKPROF statistics not supported by the raw wait events, but the wait event summary included in the TKPROF summary also is not supported by the raw wait events.  Where did those number from TKPROF originate?

Well, let’s just process the 10046 trace file using TKPROF from 11.2.0.2 to confirm the output:

SQL ID: 1ahnbczb20gdx Plan Hash: 1751280057

UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') 
WHERE
 OBJECT_ID = :B1 

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    600      3.57       3.64        884     144451     426496       50000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      601      3.57       3.64        884     144451     426496       50000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64     (recursive depth: 1)
Number of plan statistics captured: 600

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  T2 (cr=241 pr=1 pw=0 time=5550 us)
       100         83        100   INDEX UNIQUE SCAN IND_T2_OBJ (cr=106 pr=0 pw=0 time=425 us cost=1 size=2015 card=1)(object id 103855)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file scattered read                        107        0.00          0.06
  db file sequential read                        42        0.00          0.01
  log file switch completion                      2        0.00          0.01

-

Those TKPROF numbers appear quite different; translation – it you do not like the numbers produced by TKPROF, just use a different version of TKPROF.  :-)

It appears that TKPROF in 11.2.0.1 potentially lies when reporting on a trace file generated by Oracle Database 11.2.0.2.  I wonder if this problem is caused by the large cursor number in 11.2.0.2+, or if TKPROF in 11.2.0.1 also has the same problem with trace files generated by Oracle Database 11.2.0.1?

Is anyone able to reproduce the problem reported by the OP?

If you wish to experiment with my trace file and TKPROF summaries, you may download the following file:

or1122p_ora_1808.zip

When you download the file, rename the download from or1122p_ora_1808-zip.doc to or1122p_ora_1808.zip.  The enclosed or1122p_ora_1808.trc file is the raw 10446 trace file, or1122p_ora_1808.txt is the 11.2.0.1 TKPROF generated output file, and or1122p_ora_1808-2.txt is the 11.2.0.2 generated output file.








Follow

Get every new post delivered to your Inbox.

Join 141 other followers