February 13, 2012 (Modified February 14, 2012)
It seems that I often wonder about the things that I read… is it really true? Several years ago, one of the items that I wondered about is whether or not an execution plan for a SQL statement could change magically simply because the Oracle RDBMS knows that it is being watched (a bit short-sighted, but stay with me for a couple of minutes). When you first learn to read raw 10046 extended SQL trace files, you might also start to wonder whether or not enabling a 10046 trace could make the Oracle RDBMS suddenly start to behave differently.
Let’s take a quick look at a small portion of a 11.2.0.2 trace file:
PARSING IN CURSOR #371254768 len=53 dep=0 uid=62 oct=3 lid=62 tim=184435767875 hv=1334288504 ad='7ffb8c1be40' sqlid='a75xc757sg83s' SELECT /*+ INDEX(T3) */ * FROM T3 WHERE C1<=200 END OF STMT PARSE #371254768:c=0,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=216260220,tim=184435767874 EXEC #371254768:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=216260220,tim=184435767947 WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=184435767976 WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358 WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704 FETCH #371254768:c=0,e=764,p=16,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=216260220,tim=184435768757
In the above, notice the mis=1 entry on the PARSE #371254768 line – that entry indicates a hard parse, a re-optimization of the SQL statement by the query optimizer. If this SQL statement used bind variables, a feature known as bind variable peeking (introduced in Oracle 9.0.1) would take place during re-optimization, which might provide the optimizer with more information (with the help of a histogram, for instance) and potentially result in a change to the SQL statement’s execution plan.
(A partially related note: I just recently placed an order for the book “Oracle Database 11gR2 Performance Tuning Cookbook“, and while taking a quick peek at two or three pages in the book’s preview on Amazon, I found an error related to the above mentioned feature.)
Let’s take a look at a quick example of the above situation. We will start by creating a table, inserting 100,000 rows where 20% of the rows have the value 0 in column C2, creating an index on column C2, and gathering statistics with histograms:
CREATE TABLE T5(
C1 NUMBER NOT NULL,
C2 NUMBER NOT NULL,
C3 VARCHAR2(300) NOT NULL);
INSERT INTO
T5
SELECT
ROWNUM C1,
DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
RPAD('A',300,'A') C3
FROM
DUAL
CONNECT BY
LEVEL<=100000;
COMMIT;
CREATE INDEX IND_T5_C2 ON T5(C2);
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T5',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR ALL COLUMNS SIZE 254')
Now for the first segment of the test script, where a single row will be selected from the table. To save space, I will not show the output from the select of the table T5, but will show the DBMS_XPLAN output:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TraceFindMe';
SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4
SELECT
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID cmm43s6usjbk1, child number 0
-------------------------------------
SELECT C1 FROM T5 WHERE C2=:V2
Plan hash value: 3443248787
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T5 | 1 | 10 | 2 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T5_C2 | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
An index range scan, that is reasonable. Let’s change the value of the bind variable so that 20% of the rows from the table will be selected, and take a look at the execution plan:
EXEC :V2:=0
SELECT
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID cmm43s6usjbk1, child number 0
-------------------------------------
SELECT C1 FROM T5 WHERE C2=:V2
Plan hash value: 3443248787
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T5 | 1 | 10 | 2 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T5_C2 | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Notice in the above that the child number is still 0 and that the execution plan remained the same, even though we requested the retrieval of 20% of the rows from table T5. In Oracle Database 11.1 and above, adaptive cursor sharing might eventually step in to change the execution plan for this bind variable value to use a full table scan, but that change could not happen on the first execution.
Now, we will enable a 10046 trace, set the bind variable value to the second value listed above, and return the execution plan:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
EXEC :V2:=0
SELECT
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID cmm43s6usjbk1, child number 1
-------------------------------------
SELECT C1 FROM T5 WHERE C2=:V2
Plan hash value: 2002323537
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 358 (100)| |
|* 1 | TABLE ACCESS FULL| T5 | 19685 | 192K| 358 (1)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
Notice in the above output that while the SQL_ID has remained constant, the child number is now 1, and the execution plan changed to a full table scan. Bind variable peeking and the histogram on column C2 provided the optimizer with enough information to result in an execution plan change.
Let’s switch back to the original bind variable value, which will result in a single row being returned:
SELECT
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID cmm43s6usjbk1, child number 1
-------------------------------------
SELECT C1 FROM T5 WHERE C2=:V2
Plan hash value: 2002323537
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 358 (100)| |
|* 1 | TABLE ACCESS FULL| T5 | 19685 | 192K| 358 (1)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
Note that child cursor 1 is still used – a full table scan where an index range scan was used previous to enabling a 10046 trace. So, while we have not examined execution times, we have now seen cases where a query could potentially execute faster or slower due to a change in the execution plan after a 10046 extended SQL trace is enabled.
—
Let’s try one more time with the 10046 trace still enabled:
SELECT
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID cmm43s6usjbk1, child number 2
-------------------------------------
SELECT C1 FROM T5 WHERE C2=:V2
Plan hash value: 3443248787
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T5 | 1 | 10 | 2 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T5_C2 | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Now the child cursor number is displayed as 2, and the execution plan returned to an index range scan. Adaptive cursor sharing kicked in and caused a re-optimization of the SQL statement.
Let’s disable the 10046 extended SQL trace:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
A quick look at a small (marked up) portion of the raw 10046 extended SQL trace file – the first execution with the 10046 trace enabled:
PARSING IN CURSOR #429376080 len=20 dep=0 uid=62 oct=47 lid=62 tim=11461702777 hv=1269726367 ad='7ffb76adba8' sqlid='5dxda7t5uwz4z' BEGIN :V2:=0; END; END OF STMT PARSE #429376080:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11461702777 WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461702853 EXEC #429376080:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11461702867 WAIT #429376080: nam='SQL*Net message from client' ela= 1401 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461704296 CLOSE #429376080:c=0,e=12,dep=0,type=0,tim=11461704325 ===================== PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=11461704495 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1' SELECT C1 FROM T5 WHERE C2=:V2 END OF STMT PARSE #429376080:c=0,e=152,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=11461704494 <--- Hard Parse EXEC #429376080:c=0,e=784,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2002323537,tim=11461705325 WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461705357 FETCH #429376080:c=0,e=35,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2002323537,tim=11461705408 ... WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11463556616 FETCH #429376080:c=0,e=21,p=0,cr=1,cu=0,mis=0,r=4,dep=0,og=1,plh=2002323537,tim=11463556630 STAT #429376080 id=1 cnt=20000 pid=0 pos=1 obj=73243 op='TABLE ACCESS FULL T5 (cr=5813 pr=0 pw=0 time=15413 us cost=358 size=196850 card=19685)' ...
In the above, notice the mis=1 entry on the PARSE #429376080 line – the optimizer hard parsed the SQL statement. Moving down a bit in the trace file, the second execution with the changed bind variable value:
PARSING IN CURSOR #429376080 len=20 dep=0 uid=62 oct=47 lid=62 tim=11505336665 hv=1039981032 ad='7ffb873a408' sqlid='857u964yztqg8' BEGIN :V2:=4; END; END OF STMT PARSE #429376080:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11505336664 WAIT #429376080: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505336754 EXEC #429376080:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11505336769 WAIT #429376080: nam='SQL*Net message from client' ela= 2382 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505339191 CLOSE #429376080:c=0,e=13,dep=0,type=0,tim=11505339229 ===================== PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=11505339288 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1' SELECT C1 FROM T5 WHERE C2=:V2 END OF STMT PARSE #429376080:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=11505339288 <--- NO Hard Parse EXEC #429376080:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=11505339355 WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505339381 FETCH #429376080:c=0,e=296,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2002323537,tim=11505339693 ...
In the above, notice the mis=0 entry on the PARSE #429376080 line – the optimizer did NOT re-optimize this SQL statement, so the execution plan remained a full table scan. Now the final section that was influenced by adaptive cursor sharing:
PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=12566538414 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1' SELECT C1 FROM T5 WHERE C2=:V2 END OF STMT PARSE #429376080:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=12566538414 <--- NO Hard Parse EXEC #429376080:c=0,e=1594,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3443248787,tim=12566540065 <--- Hard Parse WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=12566540198 FETCH #429376080:c=0,e=29,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3443248787,tim=12566540245
In the above, notice the mis=0 entry on the PARSE #429376080 line – the optimizer did NOT re-optimize this SQL statement during the parse phase. However, remember that the cursor number changed from the previous value of 1 to 2; the above EXEC #429376080 contains mis=1, so a hard parse was performed during the execution phase.
—
You might be thinking that maybe the execution plans can only change if we use bind variables when histograms are present. Let’s try another experiment. First, we will create a table, create an index on that table, insert 100,000 rows with the same characteristics as those found in table T5, and NOT collect statistics:
CREATE TABLE T6 (
C1 NUMBER NOT NULL,
C2 NUMBER NOT NULL,
C3 VARCHAR2(300) NOT NULL);
CREATE INDEX IND_T6_C2 ON T6(C2);
INSERT INTO
T6
SELECT
ROWNUM C1,
DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
RPAD('A',300,'A') C3
FROM
DUAL
CONNECT BY
LEVEL<=100000;
COMMIT;
Let’s repeat the previous test case:
SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4
SELECT
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID 9krhnbpjpvpwh, child number 0
-------------------------------------
SELECT C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 1 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 26 | 1 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
The above shows that dynamic sampling was used during the hard parse, and as expected an index range scan was performed. Part 2 of the previous test script:
EXEC :V2:=0
SELECT
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID 9krhnbpjpvpwh, child number 0
-------------------------------------
SELECT C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 1 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 26 | 1 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | | 1 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
Again, nothing new – no hard parse when the bind variable was changed, and so the index was still used. Part 3 of the previous test script:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
EXEC :V2:=0
SELECT
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID 9krhnbpjpvpwh, child number 1
-------------------------------------
SELECT C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 142 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 34140 | 866K| 142 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 34140 | | 142 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
There was a hard parse, as is noted by the change in the child cursor number, yet the optimizer still decided that it was most efficient to perform an index range scan. The optimizer estimated that 34,140 rows would be returned with an estimated size of 866KB. You might recall that earlier the same test for table T5 showed the following execution plan:
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 358 (100)| |
|* 1 | TABLE ACCESS FULL| T5 | 19685 | 192K| 358 (1)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
With a histogram (and without dynamic sampling), the optimizer estimated that 19,685 rows would be returned with an estimated size of 192KB – and in that case a full table scan was performed. But why was a full table scan not performed when experimenting with dynamic sampling? Is it possible that if the query optimizer uses dynamic sampling, that the execution plan is NOT subject to change when a 10046 extended SQL trace is enabled, or is there a simplier cause?
Let’s try executing the query with a FULL hint:
SELECT /*+ FULL(T6) */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID bhm179jq4vvca, child number 0
-------------------------------------
SELECT /*+ FULL(T6) */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 1930642322
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 357 (100)| |
|* 1 | TABLE ACCESS FULL| T6 | 34140 | 866K| 357 (1)| 00:00:01 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
Well, that explains part of the issue. While the calculated cost of the full table scan access path is 357 (very close to the 358 calculated for the same SQL statement that accessed table T5), the calculated cost of the index access path was only 142 – the lowest calculated cost access path wins.
What if we force an index access path for table T5 with the same value of 0 for the bind variable. Will the calculated cost also be roughly 142?
SELECT /*+ INDEX(T5) */
C1
FROM
T5
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
SQL_ID 5y34jm13up8xh, child number 0
-------------------------------------
SELECT /*+ INDEX(T5) */ C1 FROM T5 WHERE C2=:V2
Plan hash value: 3443248787
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 1826 (100)| |
| 1 | TABLE ACCESS BY INDEX ROWID| T5 | 19685 | 192K| 1826 (1)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IND_T5_C2 | 19685 | | 43 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Obviously, no – otherwise the index access path would have been selected for table T5 also – as shown above, the cost is actually 1826.
—-
The challenge (drifting a bit from the topic of this article): If dynamic sampling is used, and the optimizer knows that a many (possibly 34%) of the rows will be returned when the query is executed, why is an index access path used? In other words, what causes the index access path to be calculated so cheaply when compared to the calculated cost for the same access path with table T5? Is the above simply a bug found in Oracle Database 11.2.0.2, or is there a better explanation?
–
Added February 14, 2012:
One person (Narendra) noticed that there appeared to be a bug in the optimizer’s calculations. If you closely examine the execution plans above, you just might notice that the Cost displayed on the INDEX RANGE SCAN operation’s line of the execution plan (142) is identical to the Cost displayed on its the parent operation TABLE ACCESS BY INDEX ROWID (142). As is probably well known, a parent operation’s Cost, Buffers, Reads, and various other columns display their child statistics summed with the statistics that are directly associated with the parent operation. Take another look at a portion of one of the earlier execution plans:
----------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 142 (100)| | | 1 | TABLE ACCESS BY INDEX ROWID| T6 | 34140 | 866K| 142 (0)| 00:00:01 | |* 2 | INDEX RANGE SCAN | IND_T6_C2 | 34140 | | 142 (0)| 00:00:01 | -----------------------------------------------------------------------------------------
The cost displayed for the TABLE ACCESS BY INDEX ROWID operation should be greater than the cost displayed for the index access – unless the optimizer forgot that the table must be accessed when dynamic sampling is performed. Oracle Database 11.2.0.1 and 11.2.0.2 appear to be affected by this particular bug, while Oracle Database 10.2.0.5 and 11.1.0.7 seem to under-estimate the cost of the table access when dynamic sampling is performed. As such, if statistics on some of the tables (for instance temp tables) are locked without any statistics set on the tables (to force dynamic sampling), there could be a minor issue that becomes a more significant issue when upgrading to 11.2.0.1 or 11.2.0.2.
Recreating the same test table as earlier:
DROP TABLE T6 PURGE;
CREATE TABLE T6 (
C1 NUMBER NOT NULL,
C2 NUMBER NOT NULL,
C3 VARCHAR2(300) NOT NULL);
CREATE INDEX IND_T6_C2 ON T6(C2);
INSERT INTO
T6
SELECT
ROWNUM C1,
DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
RPAD('A',300,'A') C3
FROM
DUAL
CONNECT BY
LEVEL<=100000;
COMMIT;
The first portion of the test:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10053NO10046TraceFindMe';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 (100)| 1 |00:00:00.01 | 4 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 1 | 1 (0)| 1 |00:00:00.01 | 4 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 1 |00:00:00.01 | 3 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 4
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
The second portion of the test:
EXEC :V2:=0
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 (100)| 20000 |00:00:00.06 | 6981 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 1 | 1 (0)| 20000 |00:00:00.06 | 6981 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 20000 |00:00:00.03 | 1410 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 4
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
Notice in the above that the execution plan has not changed, and the peeked bind variable value is still 4 (this is expected).
The third portion of the test:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '1005310046TraceFindMe';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
EXEC :V2:=0
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 49 (100)| 20000 |00:00:00.06 | 6944 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 18399 | 49 (0)| 20000 |00:00:00.06 | 6944 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 18399 | 49 (0)| 20000 |00:00:00.03 | 1373 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
Notice in the above that the Cost displayed for the INDEX RANGE SCAN operation is identical to the Cost displayed for the TABLE ACCESS BY INDEX ROWID – also notice the low estimated Cost for the index access (this might be a reasonable value, as will be shown below).
The fourth portion of the test, checking the cost of the full table scan access path:
SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
Plan hash value: 1930642322
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1579 (100)| 20000 |00:00:00.05 | 5815 |
|* 1 | TABLE ACCESS FULL| T6 | 1 | 18399 | 1579 (5)| 20000 |00:00:00.05 | 5815 |
-------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
Note
-----
- dynamic sampling used for this statement (level=2)
So, the calculated cost of the full table scan access path is quite high compared to the cost of the index access path.
Let’s try an undocumented OPT_ESTIMATE hint to see what happens:
SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 (100)| 20000 |00:00:00.06 | 6944 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 20000 | 1 (0)| 20000 |00:00:00.06 | 6944 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 20000 |00:00:00.02 | 1373 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Now the calculated Cost of the index access path is just 1 – bad idea for a solution.
Let’s collect statistics on the table with a histogram on column C2 to see what happens:
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T6',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR COLUMNS C2 SIZE 254',NO_INVALIDATE=>FALSE)
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 1930642322
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1582 (100)| 20000 |00:00:00.05 | 5814 |
|* 1 | TABLE ACCESS FULL| T6 | 1 | 19685 | 1582 (5)| 20000 |00:00:00.05 | 5814 |
-------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
The optimizer now selected to use a full table scan, rather than an index access path.
Let’s check the cost of the index access path:
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID 4nqwgus0ghxmc, child number 0
-------------------------------------
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE
C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1847 (100)| 20000 |00:00:00.07 | 6944 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 19685 | 1847 (2)| 20000 |00:00:00.07 | 6944 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 19685 | 44 (12)| 20000 |00:00:00.02 | 1373 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
–
The results of the test from 10.2.0.5:
The first portion of the test:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10053NO10046TraceFindMe';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 2 (100)| 1 |00:00:00.01 | 4 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 1 | 2 (0)| 1 |00:00:00.01 | 4 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 1 |00:00:00.01 | 3 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 4
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement
Notice in the above output that the Cost displayed for the TABLE ACCESS BY INDEX ROWID operation is 2, while on 11.2.0.2 it was 1.
The second portion of the test script on 10.2.0.5:
EXEC :V2:=0
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 2 (100)| 20000 |00:00:00.04 | 6969 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 1 | 2 (0)| 20000 |00:00:00.04 | 6969 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 20000 |00:00:00.01 | 1407 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 4
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement
No change in the execution plan, as expected.
The third portion of the script on 10.2.0.5:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '1005310046TraceFindMe';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
EXEC :V2:=0
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 209 (100)| 20000 |00:00:00.02 | 6932 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 20556 | 209 (0)| 20000 |00:00:00.02 | 6932 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 20556 | 49 (0)| 20000 |00:00:00.01 | 1370 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Note
-----
- dynamic sampling used for this statement
Notice in the output above the that while the cost of the TABLE ACCESS BY INDEX ROWID operation is significantly higher than the INDEX RANGE SCAN child operation, the Cost was not high enough to result in a full table scan.
Checking the calculated cost of a full table scan:
SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bk8rwkf0ab8h5, child number 0
-------------------------------------
SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 1930642322
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 358 (100)| 20000 |00:00:00.02 | 5815 |
|* 1 | TABLE ACCESS FULL| T6 | 1 | 20556 | 358 (1)| 20000 |00:00:00.02 | 5815 |
-------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
Note
-----
- dynamic sampling used for this statement
358 is greater than 209, so no full table scan without a hint.
OPT_ESTIMATE hint test:
SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bud5avdhnmssf, child number 0
-------------------------------------
SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 (100)| 20000 |00:00:00.04 | 6932 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 20000 | 1 (0)| 20000 |00:00:00.04 | 6932 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 1 | 1 (0)| 20000 |00:00:00.01 | 1370 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
Gather statistics on 10.2.0.5 with a histogram on column C2, then repeat the test:
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T6',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR COLUMNS C2 SIZE 254',NO_INVALIDATE=>FALSE)
SELECT /*+ GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 1930642322
-------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
-------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 358 (100)| 20000 |00:00:00.02 | 5815 |
|* 1 | TABLE ACCESS FULL| T6 | 1 | 19685 | 358 (1)| 20000 |00:00:00.02 | 5815 |
-------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("C2"=:V2)
The optimizer determined that a full table scan would be most efficient.
Let’s check the cost of the index access path on 10.2.0.5:
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */
C1
FROM
T6
WHERE
C2=:V2;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
SQL_ID 4nqwgus0ghxmc, child number 0
-------------------------------------
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */ C1 FROM T6 WHERE C2=:V2
Plan hash value: 4242288932
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | Cost (%CPU)| A-Rows | A-Time | Buffers |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1822 (100)| 20000 |00:00:00.02 | 6932 |
| 1 | TABLE ACCESS BY INDEX ROWID| T6 | 1 | 19685 | 1822 (1)| 20000 |00:00:00.02 | 6932 |
|* 2 | INDEX RANGE SCAN | IND_T6_C2 | 1 | 19685 | 39 (0)| 20000 |00:00:00.01 | 1370 |
----------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - (NUMBER): 0
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("C2"=:V2)
The Cost of 1822 is greater than the Cost of 358 for the full table scan access path, so that explains why the full table scan access path was selected.
Charles Hooper's Oracle Notes 
Recent Comments