To N or Not to N, is SYS_OP_C2C the Question; Oracle NVARCHAR Slow?

8 02 2015

February 8, 2015

I was recently contacted about an odd performance issue with a software product named TDM, where certain SQL statements submitted to an Oracle 9.2.x database required roughly 30 seconds to execute when a nearly instantaneous response was expected.  The person who reported the issue to me provided a sample SQL statement that appeared something similar to the following:

SELECT
  DATA
FROM 
  MVIS_DATA 
WHERE 
  TOOLID = N'112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;

In the SQL statement, notice the N character that is immediately before ‘112’ in the SQL statement.  The person indicated that the SQL statement executed quickly if that N character were removed from the SQL statement.  At this time the developer of that application is unwilling to release a bug fix to remove the N character from this (and likely other) SQL statements.

I did not initially have the table datatype descriptions (retrieved with DESC MVIS_DATA), so I made a couple of guesses about the datatypes.  What if the TOOLID column was defined as a number, and is it the primary key column for the table (indicating that there must be an index on that column)?  It might be the case that the developer of the application decided that in all SQL statements that are submitted with literal values (rather than using bind variables), that all numbers would be submitted in single quotes.  I created a testing table for a mock up in Oracle Database 11.2.0.2:

CREATE TABLE MVIS_DATA_NUM (
  TOOLID NUMBER,
  DATATYPE NUMBER,
  COMMISSIONID NUMBER,
  OPERATIONID NUMBER,
  COMMISSIONLISTPOS NUMBER,
  DATA VARCHAR2(100),
  PRIMARY KEY (TOOLID));
 
INSERT INTO
  MVIS_DATA_NUM
SELECT
  ROWNUM TOOLID,
  MOD(ROWNUM,2) DATATYPE,
  NULL COMMISSIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) OPERATIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) COMMISSIONLISTPOS,
  LPAD('A',100,'A') DATA
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;
 
COMMIT;
 
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'MVIS_DATA_NUM',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

With the testing table created with 100,000 rows, and statistics gathered for the table and primary key index, I then tried executing a query and retrieving the execution plan for that query so that I could determine if the Predicate Information section of the execution plan provided any clues.  I executed the following, the first SQL statement retrieved one row, and the second SQL statement retrieved the execution plan for the first SQL statement:

SET LINESIZE 140
SET PAGESIZE 1000
 
SELECT
  DATA
FROM 
  MVIS_DATA_NUM
WHERE 
  TOOLID = N'112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

The execution plan output is as follows:

SQL_ID  gzzrppktqkbmu, child number 0
-------------------------------------
SELECT   DATA FROM   MVIS_DATA_NUM WHERE   TOOLID = N'112'   AND
DATATYPE = 0   AND COMMISSIONID IS NULL   AND OPERATIONID IS NULL   AND
COMMISSIONLISTPOS IS NULL
 
Plan hash value: 1080991
 
---------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |               |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS BY INDEX ROWID| MVIS_DATA_NUM |     1 |   113 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | SYS_C0050817  |     1 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("OPERATIONID" IS NULL AND "COMMISSIONLISTPOS" IS NULL AND
              "DATATYPE"=0 AND "COMMISSIONID" IS NULL))
   2 - access("TOOLID"=112)

Nothing too unusual in the above execution plan, the N’112′ portion of the SQL statement was simply changed by the query optimizer to the number 112, which permitted the use of the table’s primary key index.  Obviously, Oracle Database 11.2.0.2 contains a few optimizations that are not available in Oracle Database 9.2.x, so maybe the outcome would be different in Oracle Database 9.2.x.  However, when a number value is compared to a character (for example VARCHAR2) value, Oracle Database will attempt to implicitly convert the character value to a number value when performing the comparison, so the outcome should be the same on Oracle Database 9.2.x.

What if that TOOLID column were defined as VARCHAR?  Below is another test table with that column defined as VARCHAR2:

CREATE TABLE MVIS_DATA (
  TOOLID VARCHAR2(15),
  DATATYPE NUMBER,
  COMMISSIONID NUMBER,
  OPERATIONID NUMBER,
  COMMISSIONLISTPOS NUMBER,
  DATA VARCHAR2(100),
  PRIMARY KEY (TOOLID));
 
INSERT INTO
  MVIS_DATA
SELECT
  TO_CHAR(ROWNUM) TOOLID,
  MOD(ROWNUM,2) DATATYPE,
  NULL COMMISSIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) OPERATIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) COMMISSIONLISTPOS,
  LPAD('A',100,'A') DATA
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;
 
COMMIT;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'MVIS_DATA',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

With the new test table created, let’s try the SQL statement again.  A 10053 trace file will be enabled in the event that you are interested in examining any potential automatic transformations of the SQL statement:

SET LINESIZE 140
SET PAGESIZE 1000
 
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SQL_10053V';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
 
SELECT
  DATA
FROM 
  MVIS_DATA 
WHERE 
  TOOLID = N'112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
 
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT OFF';

The first of the above SQL statements output one row.  Here is the execution plan that was output:

SQL_ID  5pkwzs079jwu2, child number 0
-------------------------------------
SELECT   DATA FROM   MVIS_DATA WHERE   TOOLID = N'112'   AND DATATYPE =
0   AND COMMISSIONID IS NULL   AND OPERATIONID IS NULL   AND
COMMISSIONLISTPOS IS NULL
 
Plan hash value: 353063534
 
-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           |       |       |   227 (100)|          |
|*  1 |  TABLE ACCESS FULL| MVIS_DATA |   122 | 13908 |   227   (3)| 00:00:01 |
-------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("OPERATIONID" IS NULL AND "COMMISSIONLISTPOS" IS NULL
              AND "DATATYPE"=0 AND SYS_OP_C2C("TOOLID")=U'112' AND "COMMISSIONID" IS
              NULL))

Notice the SYS_OP_C2C function in the Predicate Information section of the execution plan, that is a clue that there might be a performance problem lurking.  Also notice that the INDEX UNIQUE SCAN operation was replaced with a TABLE ACCESS FULL operation, that is also a clue that a performance problem may be lurking.  This section of the execution plan also indicates that the N’112′ portion of the SQL statement was changed to U’112′.  Consulting the 10053 trace file indicates that the query optimizer rewrote the submitted SQL statement to the following:

SELECT
  "MVIS_DATA"."DATA" "DATA"
FROM
  "TESTUSER"."MVIS_DATA" "MVIS_DATA"
WHERE
  SYS_OP_C2C("MVIS_DATA"."TOOLID")=U'112'
  AND "MVIS_DATA"."DATATYPE"=0
  AND "MVIS_DATA"."COMMISSIONID" IS NULL
  AND "MVIS_DATA"."OPERATIONID" IS NULL
  AND "MVIS_DATA"."COMMISSIONLISTPOS" IS NULL

SYS_OP_C2C is an internal characterset conversion function.

What happens to the execution plan if the N character is removed from the SQL statement?

SELECT
  DATA
FROM 
  MVIS_DATA 
WHERE 
  TOOLID = '112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

Below is the execution plan that was output:

SQL_ID  d70jxj3ypy60g, child number 0
-------------------------------------
SELECT   DATA FROM   MVIS_DATA WHERE   TOOLID = '112'   AND DATATYPE =
0   AND COMMISSIONID IS NULL   AND OPERATIONID IS NULL   AND
COMMISSIONLISTPOS IS NULL
 
Plan hash value: 1051843381
 
--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS BY INDEX ROWID| MVIS_DATA    |     1 |   114 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | SYS_C0050814 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("OPERATIONID" IS NULL AND "COMMISSIONLISTPOS" IS NULL AND
              "DATATYPE"=0 AND "COMMISSIONID" IS NULL))
   2 - access("TOOLID"='112')

Notice that the SYS_OP_C2C function does not appear in the Predicate Information section of the execution plan this time, and that the primary key index is used, rather than requiring a full table scan.  Unfortunately, the DBMS_XPLAN.DISPLAY_CURSOR function does not exist in Oracle Database 9.2.0.x, otherwise the reason for the performance problem may have been much more readily apparent to the person who reported the issue to me.

So, what is the purpose of that N character in the SQL statement?  I recall seeing SQL statements similar to this one in the past, which converts a character string to a date:

SELECT DATE'2015-02-08' FROM DUAL;
 
DATE'2015
---------
08-FEB-15

After a fair amount of digging through the Oracle documentation, I located the following note about that N character:

“The TO_NCHAR function converts the data at run time, while the N function converts the data at compilation time.”

Interesting.  That quote suggests that the author of the SQL statement may have been trying to convert ‘112’ to a NVARCHAR2 (or NCHAR).  Time for another test, the below script creates a table with the TOOLID column defined as NVARCHAR2, populates the table with 100,000 rows, and then collects statistics on the table and its primary key index:

CREATE TABLE MVIS_DATA_N (
  TOOLID NVARCHAR2(15),
  DATATYPE NUMBER,
  COMMISSIONID NUMBER,
  OPERATIONID NUMBER,
  COMMISSIONLISTPOS NUMBER,
  DATA VARCHAR2(100),
  PRIMARY KEY (TOOLID));
 
INSERT INTO
  MVIS_DATA_N
SELECT
  TO_CHAR(ROWNUM) TOOLID,
  MOD(ROWNUM,2) DATATYPE,
  NULL COMMISSIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) OPERATIONID,
  DECODE(MOD(ROWNUM,2),0,NULL,MOD(ROWNUM,2)) COMMISSIONLISTPOS,
  LPAD('A',100,'A') DATA
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;
 
COMMIT;
 
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'MVIS_DATA_N',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

Executing the query against this table also returns one row:

SELECT
  DATA
FROM 
  MVIS_DATA_N 
WHERE 
  TOOLID = N'112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

The execution plan follows:

SQL_ID  1yuzz9rqkvnpv, child number 0
-------------------------------------
SELECT   DATA FROM   MVIS_DATA_N WHERE   TOOLID = N'112'   AND DATATYPE
= 0   AND COMMISSIONID IS NULL   AND OPERATIONID IS NULL   AND
COMMISSIONLISTPOS IS NULL
 
Plan hash value: 1044325464
 
--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS BY INDEX ROWID| MVIS_DATA_N  |     1 |   119 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | SYS_C0050815 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("OPERATIONID" IS NULL AND "COMMISSIONLISTPOS" IS NULL AND
              "DATATYPE"=0 AND "COMMISSIONID" IS NULL))
   2 - access("TOOLID"=U'112')

Notice in the above Predicate Information section that the SYS_OP_C2C function does not appear, and the N’112′ portion of the SQL statement was still changed to U’112′.  The execution plan also shows that the primary key index was used, while a full table scan was required when the TOOLID column was defined as a VARCHAR2.

The person who reported the issue to me later provide the output of DESC MVIS_DATA, which indicated that the TOOLID column was in fact defined as a VARCHAR2 column.  If this person were running a more recent version of Oracle Database, he might be able to create a function based index that uses the SYS_OP_C2C function on the TOOLID column.  Such an index might look something like this:

CREATE INDEX IND_TOOLID_FIX ON MVIS_DATA (SYS_OP_C2C("TOOLID"));

Gathering statistics on the table and its indexes, executing the original SQL statement, and outputting the execution plan:

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'MVIS_DATA',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)
 
SELECT
  DATA
FROM 
  MVIS_DATA 
WHERE 
  TOOLID = N'112' 
  AND DATATYPE = 0 
  AND COMMISSIONID IS NULL 
  AND OPERATIONID IS NULL 
  AND COMMISSIONLISTPOS IS NULL;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

The first of the above queries output the expected one row, while the second query output the following execution plan:

SQL_ID  5pkwzs079jwu2, child number 1
-------------------------------------
SELECT   DATA FROM   MVIS_DATA WHERE   TOOLID = N'112'   AND DATATYPE =
0   AND COMMISSIONID IS NULL   AND OPERATIONID IS NULL   AND
COMMISSIONLISTPOS IS NULL
 
Plan hash value: 1497912695
 
----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS BY INDEX ROWID| MVIS_DATA      |     1 |   125 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_TOOLID_FIX |     1 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("OPERATIONID" IS NULL AND "COMMISSIONLISTPOS" IS NULL AND "DATATYPE"=0
              AND "COMMISSIONID" IS NULL))
   2 - access("MVIS_DATA"."SYS_NC00007$"=U'112')

In the Predicate Information section of the execution plan, notice the absence of the SYS_OP_C2C function on the TOOLID column – those values are pre-computed in the virtual column (SYS_NC00007$) created for the function based index.  An index range scan is reported in the execution plan, rather than an index unique scan (the function based index, when created, was not declared as unique), so the SQL statement should execute much faster than the roughly 30 seconds required by the SQL statement without the function based index.

So, what are the options that were mentioned above?

  • Have the application programmer fix the SQL statements.
  • Upgrade to a version of Oracle Database (if that version is supported by the application) that supports the SYS_OP_C2C function, and create a function based index using that function.
  • If the TOOLID column only contains numbers, that column should be defined as NUMBER, rather than VARCHAR2.  Consider redefining that column as a NUMBER datatype.
  • If that N character is always used when this column is referenced, that column probably should be defined as NVARCHAR2 rather than VARCHAR2.  Consider redefining that column as a NVARCHAR2 datatype.
  • Consider that the application is working as designed, and that it is nice to receive 30 second breaks every now and then.
  • Take a DUMP and share it with the application developer.  On second thought, such an approach may have limited success in helping to solve this problem.

Here is a little experiment with the DUMP function, which reveals Oracle’s internal representation of data – refer to the Internal datatypes and datatype codes in the Oracle documentation for help in decoding the Typ= values.

SELECT DUMP(112) A FROM DUAL;
 
A
---------------------
Typ=2 Len=3: 194,2,13
 
/* ------------------- */
SELECT DUMP(TO_CHAR(112)) A FROM DUAL;
 
A
---------------------
Typ=1 Len=3: 49,49,50
 
/* ------------------- */
SELECT DUMP('112') A FROM DUAL;
 
A
----------------------
Typ=96 Len=3: 49,49,50
 
/* ------------------- */
SELECT DUMP(N'112') A FROM DUAL;
 
A
----------------------------
Typ=96 Len=6: 0,49,0,49,0,50
 
/* ------------------- */
SELECT DUMP(SYS_OP_C2C('112'))  A FROM DUAL;
 
A
----------------------------
Typ=96 Len=6: 0,49,0,49,0,50
 
/* ------------------- */
SELECT DUMP(TO_NCHAR('112')) A FROM DUAL;
 
A
---------------------------
Typ=1 Len=6: 0,49,0,49,0,50

It is possibly interesting to note that the internal representation for N’112′ is CHAR (or NCHAR), while the internal representation for TO_NCHAR(‘112′) (and TO_NCHAR(112)) is VARCHAR2 (or NVARCHAR2).

This blog’s statistics indicate that the search engine search term Oracle NVARCHAR slow resulted in two page views of this blog yesterday.  I can’t help but wonder if the person who performed that search might have been helped by some of the above analysis.





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.








Follow

Get every new post delivered to your Inbox.

Join 160 other followers