February 2, 2010
(Back to the Previous Post in the Series)
In the first blog article in this series, we explored several methods for generating execution plans, specifcally, we saw how to:
- Display the actual (TYPICAL) execution plan for a SQL statement with estimated cardinality and costs.
- Display the actual (ALLSTATS LAST) execution plan for a SQL statement using the GATHER_PLAN_STATISTICS hint to compare the estimated cardinality with the actual number of rows returned from each operation in the plan, and obtain the actual final execution time (timing of the intermediate steps might not be close to actual time).
- Display the actual (ALLSTATS LAST) execution plan for a SQL statement with the STATISTICS_LEVEL parameter set to ALL at the session level to obtain the final execution time and close estimates for each of the intermediate steps (in some cases, a significant increase in execution time was experienced).
- Compare the changes in the actual execution plan when changing the OPTIMIZER_MODE parameter between ALL_ROWS, FIRST_ROWS_1, and CHOOSE. Note that setting the OPTIMIZER_MODE to FIRST_ROWS_1 may have caused the optimizer to under-estimate the number of rows that will be returned, as shown in the execution plan.
- Display a possibly correct execution plan with SQL*Plus’ AUTOTRACE and with EXPLAIN PLAN, and explore some of the problems that might be encountered when relying on those plans.
- See the effects of bind peeking on an execution plan.
- Retrieve the execution plan by setting event 10132.
- Read the execution plan directly from a 10046 trace file.
- Process the trace file with TKPROF, and one of the potential problems caused by telling TKPROF to generate explain plans.
The first blog article in this article series used the 64 bit version of Oracle Database 10.2.0.2 (with OPTIMIZER_FEATURES_ENABLE set to 10.2.0.1). It might be interesting to compare the output of the 64 bit version of Oracle 11.2.0.1 with that of Oracle 10.2.0.2 (note that the server running 11.2.0.1 is a bit faster than the server running 10.2.0.2). Comparing the outputs might answer the question of whether or not there is a bug in Oracle 10.2.0.2, for instance, relating the the cardinality estimates displayed in execution plans when the OPTIMIZER_MODE was set to FIRST_ROWS_1 – if the same output is present in 11.2.0.1, that probably means that the optimizer is working as designed. Obviously, this article will use the same table definition for T1, T2, T3, and T4 that were specified in the first article.
First, we will generate an execution plan for a SQL statement with the OPTIMIZER_MODE set to ALL_ROWS:
SET LINESIZE 150 ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; C1 C2 --- ---------- 1 1AAAAAAAAA 2 2AAAAAAAAA 3 3AAAAAAAAA 4 4AAAAAAAAA 5 5AAAAAAAAA 6 6AAAAAAAAA 7 7AAAAAAAAA 8 8AAAAAAAAA 9 9AAAAAAAAA 10 10AAAAAAAA
The typical way to display an execution plan for a SQL statement that was just executed is as follows (note that the third parameter, the FORMAT parameter, could have also been set to NULL to produce the same result):
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL')); SQL_ID 9dq71tc7vasgu, child number 0 ------------------------------------- SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 985299768 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 10219 (100)| | |* 1 | HASH JOIN | | 9 | 2394 | 10219 (1)| 00:02:03 | |* 2 | TABLE ACCESS FULL | T3 | 10 | 50 | 10214 (1)| 00:02:03 | | 3 | TABLE ACCESS BY INDEX ROWID| T1 | 10 | 2610 | 4 (0)| 00:00:01 | |* 4 | INDEX RANGE SCAN | SYS_C0017307 | 10 | | 3 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - access("T1"."C1"="T3"."C1") 2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1">=1 AND "T1"."C1"<=10)
In the above, note that the calculated cost of the execution plan is 10219 (NOWORKLOAD CPU statistics). Now, a little more experimentation, setting OPTIMIZER_MODE to FIRST_ROWS (Oracle assumes that only the first row will be retrieved, and the rest will likely be discarded):
ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1'; SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL')); SQL_ID 9dq71tc7vasgu, child number 1 ------------------------------------- SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 2322422896 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 3073 (100)| | | 1 | NESTED LOOPS | | | | | | | 2 | NESTED LOOPS | | 2 | 532 | 3073 (1)| 00:00:37 | |* 3 | TABLE ACCESS FULL | T3 | 7 | 35 | 3066 (1)| 00:00:37 | |* 4 | INDEX UNIQUE SCAN | SYS_C0017307 | 1 | | 1 (0)| 00:00:01 | | 5 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 261 | 2 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=10 AND "T1"."C1">=1))
In the above, notice that by changing the optimizer mode from ALL_ROWS to FIRST_ROWS_1 a new execution plan was created (the child number has increased by 1 and the Plan hash value has changed) that now uses two nested loops joins (first joining the index for table T1 with the table T3), rather than a hash join, and the calculated cost has decreased to 3073. You might be wondering why Oracle did not pick this execution plan with the nested loops joins, rather than the hash join when the OPTIMIZER_MODE was set to ALL_ROWS, since this plan has a lower calculated cost – note that Oracle 11.2.0.1 is estimating the same number of rows to be returned as Oracle 10.2.0.2. But, we really do not know anything about performance from just looking at the above plans. So, let’s repeat the test again, changing the SQL statement so that we are able to pass in ‘ALLSTATS LAST’ as the format parameter for the DBMS_XPLAN call:
ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID ddnbt67ftu9ds, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 985299768 ---------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem | ---------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.07 | 37170 | | | | |* 1 | HASH JOIN | | 1 | 9 | 10 |00:00:00.07 | 37170 | 1452K| 1452K| 1365K (0)| |* 2 | TABLE ACCESS FULL | T3 | 1 | 10 | 10 |00:00:00.01 | 37164 | | | | | 3 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10 | 10 |00:00:00.01 | 6 | | | | |* 4 | INDEX RANGE SCAN | SYS_C0017307 | 1 | 10 | 10 |00:00:00.01 | 4 | | | | ---------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - access("T1"."C1"="T3"."C1") 2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1">=1 AND "T1"."C1"<=10)
The query completed in 0.07 seconds, retrieved 10 rows, and used 1,365 * 1,024 bytes of memory during the in-memory hash join. No blocks were read from disk (the query was previously executed, and the table and index blocks managed to remain in the buffer cache).
ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1'; SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID ddnbt67ftu9ds, child number 1 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 2322422896 ------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.01 | 37189 | | 1 | NESTED LOOPS | | 1 | | 10 |00:00:00.01 | 37189 | | 2 | NESTED LOOPS | | 1 | 2 | 10 |00:00:00.01 | 37179 | |* 3 | TABLE ACCESS FULL | T3 | 1 | 7 | 10 |00:00:00.01 | 37165 | |* 4 | INDEX UNIQUE SCAN | SYS_C0017307 | 10 | 1 | 10 |00:00:00.01 | 14 | | 5 | TABLE ACCESS BY INDEX ROWID| T1 | 10 | 1 | 10 |00:00:00.01 | 10 | ------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=10 AND "T1"."C1">=1))
As shown above, with the FIRST_ROWS_1 optimizer mode, the query completed in 0.01 seconds.
The GATHER_PLAN_STATISTICS hint is helpful because it allows DBMS_XPLAN to output the actual execution statistics for the previous SQL statement. If you do not want to use that hint, it is also possible to change the STATISTICS_LEVEL to ALL at the session level level, as the following demonstrates:
ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; ALTER SESSION SET STATISTICS_LEVEL='ALL'; SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID 9dq71tc7vasgu, child number 2 ------------------------------------- SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 985299768 ---------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem | ---------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.07 | 37170 | | | | |* 1 | HASH JOIN | | 1 | 9 | 10 |00:00:00.07 | 37170 | 1452K| 1452K| 1424K (0)| |* 2 | TABLE ACCESS FULL | T3 | 1 | 10 | 10 |00:00:00.07 | 37164 | | | | | 3 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10 | 10 |00:00:00.01 | 6 | | | | |* 4 | INDEX RANGE SCAN | SYS_C0017307 | 1 | 10 | 10 |00:00:00.01 | 4 | | | | ---------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - access("T1"."C1"="T3"."C1") 2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1">=1 AND "T1"."C1"<=10)
Note that the change to the STATISTICS_LEVEL caused another hard parse for the SQL statement, and the child number is now listed as 2. For some reason, the amount of memory required for the hash join has increased slightly. If you look closely, you will also notice that the execution time remained the same before and after the changing of the STATISTICS_LEVEL parameter.
Let’s try again with the FIRST_ROWS_1 value specified for OPTIMIZER_MODE.
ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1'; SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID 9dq71tc7vasgu, child number 3 ------------------------------------- SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10 Plan hash value: 2322422896 ------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.07 | 37189 | | 1 | NESTED LOOPS | | 1 | | 10 |00:00:00.07 | 37189 | | 2 | NESTED LOOPS | | 1 | 2 | 10 |00:00:00.07 | 37179 | |* 3 | TABLE ACCESS FULL | T3 | 1 | 7 | 10 |00:00:00.07 | 37165 | |* 4 | INDEX UNIQUE SCAN | SYS_C0017307 | 10 | 1 | 10 |00:00:00.01 | 14 | | 5 | TABLE ACCESS BY INDEX ROWID| T1 | 10 | 1 | 10 |00:00:00.01 | 10 | ------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1)) 4 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=10 AND "T1"."C1">=1))
Note again that there was a hard parse, and the child number increased by 1. This time, rather than completing in 0.01 seconds, the query required 0.07 seconds.
Let’s try again, this time using bind variables rather than constants (literals):
ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; ALTER SESSION SET STATISTICS_LEVEL='TYPICAL'; VARIABLE N1 NUMBER VARIABLE N2 NUMBER EXEC :N1:=1 EXEC :N2:=10 SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID cvq22z77c8fww, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 744086632 ----------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem | ----------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.07 | 37170 | | | | |* 1 | FILTER | | 1 | | 10 |00:00:00.07 | 37170 | | | | |* 2 | HASH JOIN | | 1 | 9 | 10 |00:00:00.07 | 37170 | 1452K| 1452K| 1424K (0)| |* 3 | TABLE ACCESS FULL | T3 | 1 | 10 | 10 |00:00:00.01 | 37164 | | | | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10 | 10 |00:00:00.01 | 6 | | | | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 1 | 10 | 10 |00:00:00.01 | 4 | | | | ----------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T1"."C1"="T3"."C1") 3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)
Same execution plan as we saw earlier, with the same cardinality estimates due to bind variable peeking, except now there is a FILTER operation AT ID 1 with a predicate that states that the N1 bind variable must be less than or equal to the N2 bind variable – this is an automatically generated predicate caused by the BETWEEN syntax in the SQL statement.
Now we change the value of the second bind variable to a much larger value:
EXEC :N2:=500000 SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID cvq22z77c8fww, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 744086632 -------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem | -------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 500K|00:00:08.01 | 123K| 12985 | | | | |* 1 | FILTER | | 1 | | 500K|00:00:08.01 | 123K| 12985 | | | | |* 2 | HASH JOIN | | 1 | 9 | 500K|00:00:07.72 | 123K| 12985 | 15M| 3723K| 23M (0)| |* 3 | TABLE ACCESS FULL | T3 | 1 | 10 | 500K|00:00:00.11 | 37164 | 0 | | | | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10 | 500K|00:00:06.72 | 86064 | 12985 | | | | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 1 | 10 | 500K|00:00:00.43 | 34211 | 634 | | | | -------------------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T1"."C1"="T3"."C1") 3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)
In the above, notice that there was no hard parse (same SQL_ID and child number as we saw earlier), and the E-Rows column is the same for the two DBMS_XPLAN outputs. The Used-Tmp column was not displayed (11.2.0.1 had a larger value for PGA_AGGREGATE_TARGET specified). Let’s repeat the test with the altered OPTIMIZER_MODE:
EXEC :N2:=10 ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1'; SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID cvq22z77c8fww, child number 1 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 1340904442 -------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | -------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.01 | 37189 | |* 1 | FILTER | | 1 | | 10 |00:00:00.01 | 37189 | | 2 | NESTED LOOPS | | 1 | | 10 |00:00:00.01 | 37189 | | 3 | NESTED LOOPS | | 1 | 2 | 10 |00:00:00.01 | 37179 | |* 4 | TABLE ACCESS FULL | T3 | 1 | 7 | 10 |00:00:00.01 | 37165 | |* 5 | INDEX UNIQUE SCAN | SYS_C0017307 | 10 | 1 | 10 |00:00:00.01 | 14 | | 6 | TABLE ACCESS BY INDEX ROWID| T1 | 10 | 1 | 10 |00:00:00.01 | 10 | -------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1)) EXEC :N2:=500000 SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID cvq22z77c8fww, child number 1 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 1340904442 ----------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | ----------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 500K|00:00:03.77 | 782K| 1 | |* 1 | FILTER | | 1 | | 500K|00:00:03.77 | 782K| 1 | | 2 | NESTED LOOPS | | 1 | | 500K|00:00:03.52 | 782K| 1 | | 3 | NESTED LOOPS | | 1 | 2 | 500K|00:00:02.00 | 282K| 1 | |* 4 | TABLE ACCESS FULL | T3 | 1 | 7 | 500K|00:00:00.39 | 70498 | 0 | |* 5 | INDEX UNIQUE SCAN | SYS_C0017307 | 500K| 1 | 500K|00:00:00.95 | 212K| 1 | | 6 | TABLE ACCESS BY INDEX ROWID| T1 | 500K| 1 | 500K|00:00:00.86 | 500K| 0 | ----------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))
3.77 seconds to execute the SQL statement with OPTIMIZER_MODE set to FIRST_ROWS_1 and 8.01 seconds with OPTIMIZER_MODE set to ALL_ROWS (and 0.01 seconds compared to 0.07 seconds for the execution retrieving 10 rows). Obviously, this means that we should be running with OPTIMIZER_MODE set to FIRST_ROWS_1 if we want to optimize performance, right? Well, in short No. Maybe this will be something that will be investigated in a later blog article.
Now, turning to the unanalyzed tables. We modify the original SQL statement using bind variables to point to the two tables without up-to-date statistics on the tables and their indexes:
EXEC :N2:=10 ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID 94bv1jwkzcc38, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2 Plan hash value: 2134503202 -------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem | -------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.01 | 37169 | 37128 | | | | |* 1 | FILTER | | 1 | | 10 |00:00:00.01 | 37169 | 37128 | | | | |* 2 | HASH JOIN | | 1 | 10 | 10 |00:00:00.01 | 37169 | 37128 | 711K| 711K| 1116K (0)| | 3 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 10 | 10 |00:00:00.01 | 4 | 1 | | | | |* 4 | INDEX RANGE SCAN | SYS_C0017308 | 1 | 10 | 10 |00:00:00.01 | 3 | 0 | | | | |* 5 | TABLE ACCESS FULL | T4 | 1 | 1855 | 10 |00:00:00.01 | 37165 | 37127 | | | | -------------------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T2"."C1"="T4"."C1") 4 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2) 5 - filter(("T4"."C1">=:N1 AND "T4"."C1"<=:N2)) Note ----- - dynamic sampling used for this statement (level=2)
The only change here is that Oracle is now estimating that 10 rows will be returned rather than the 9 we saw earlier, and the note below the predicate information heading that states that dynamic sampling at level 2 was used, oh – and the order of the row sources directly below the HASH JOIN line in the plan has changed just like on Oracle 10.2.0.2 (is this a problem?). Maybe dynamic sampling will be a topic for another blog article, but the topic is discussed in various books and articles on the Internet.
ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1'; SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID 94bv1jwkzcc38, child number 1 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2 Plan hash value: 2134503202 -------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem | -------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 10 |00:00:00.01 | 37169 | 37129 | | | | |* 1 | FILTER | | 1 | | 10 |00:00:00.01 | 37169 | 37129 | | | | |* 2 | HASH JOIN | | 1 | 10 | 10 |00:00:00.01 | 37169 | 37129 | 711K| 711K| 1147K (0)| | 3 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 10 | 10 |00:00:00.01 | 4 | 1 | | | | |* 4 | INDEX RANGE SCAN | SYS_C0017308 | 1 | 10 | 10 |00:00:00.01 | 3 | 0 | | | | |* 5 | TABLE ACCESS FULL | T4 | 1 | 1855 | 10 |00:00:00.01 | 37165 | 37128 | | | | -------------------------------------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T2"."C1"="T4"."C1") 4 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2) 5 - filter(("T4"."C1">=:N1 AND "T4"."C1"<=:N2)) Note ----- - dynamic sampling used for this statement (level=2)
OK, this plan changed a bit from when the SQL statement referenced tables T1 and T3. The execution plan is no longer using a nested loops join – in fact it is using the same plan as was used when the OPTIMIZER_MODE was set to ALL_ROWS (just like on Oracle 10.2.0.2).
Oracle 9i and earlier Oracle releases had a default OPTIMIZER_MODE of CHOOSE, so let’s see what happens when we use that optimizer mode with the same two tables:
ALTER SESSION SET OPTIMIZER_MODE='CHOOSE'; SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST')); SQL_ID 94bv1jwkzcc38, child number 2 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T4.C1, SUBSTR(T2.C2,1,10) C2 FROM T4, T2 WHERE T2.C1=T4.C1 AND T2.C1 BETWEEN :N1 AND :N2 Plan hash value: 1136565161 ------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | Reads | ------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 10 |00:00:00.03 | 386K| 39012 | | 1 | NESTED LOOPS | | 1 | 10 |00:00:00.03 | 386K| 39012 | | 2 | NESTED LOOPS | | 1 | 10 |00:00:00.03 | 386K| 39011 | | 3 | TABLE ACCESS FULL | T4 | 1 | 1000K|00:00:00.38 | 37165 | 37133 | |* 4 | INDEX UNIQUE SCAN | SYS_C0017308 | 1000K| 10 |00:00:02.30 | 348K| 1878 | | 5 | TABLE ACCESS BY INDEX ROWID| T2 | 10 | 10 |00:00:00.01 | 10 | 1 | ------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 4 - access("T2"."C1"="T4"."C1") filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1)) Note ----- - rule based optimizer used (consider using cbo)
Note that the Note section indicates that the rule based optimizer was used (just like with Oracle 10.2.0.2), even though the documentation for Oracle 10.2 states that as of Oracle 10.1 the RULE based optimizer is no longer supported. Also note that the execution plan is now using a nested loops join, the FILTER operation no longer appears, and the full table scan is again first joined with the index for the other table, just as it was when the OPTIMIZER_MODE was set to FIRST_ROWS_1 and the query accessed tables T1 and T3.
Let’s say that we are bored, and did not read chapter 15 by Pete Finnigan in the “Expert Oracle Practices” book… assume that column C1 contains a credit card number. Now for an experiment, we will retrieve all child cursors for SQL_ID cvq22z77c8fww with the bind variables that were submitted on the initial hard parse – be careful with who has access to this feature in a production environment, as it could expose sensitive information:
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR('cvq22z77c8fww',NULL,'ALLSTATS LAST +PEEKED_BINDS')); SQL_ID cvq22z77c8fww, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 744086632 -------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem | -------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 500K|00:00:08.01 | 123K| 12985 | | | | |* 1 | FILTER | | 1 | | 500K|00:00:08.01 | 123K| 12985 | | | | |* 2 | HASH JOIN | | 1 | 9 | 500K|00:00:07.72 | 123K| 12985 | 15M| 3723K| 23M (0)| |* 3 | TABLE ACCESS FULL | T3 | 1 | 10 | 500K|00:00:00.11 | 37164 | 0 | | | | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10 | 500K|00:00:06.72 | 86064 | 12985 | | | | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 1 | 10 | 500K|00:00:00.43 | 34211 | 634 | | | | -------------------------------------------------------------------------------------------------------------------------------------------- Peeked Binds (identified by position): -------------------------------------- 1 - (NUMBER): 1 2 - (NUMBER): 10 Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T1"."C1"="T3"."C1") 3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2) - SQL_ID cvq22z77c8fww, child number 1 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 Plan hash value: 1340904442 ----------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | ----------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | 500K|00:00:03.77 | 782K| 1 | |* 1 | FILTER | | 1 | | 500K|00:00:03.77 | 782K| 1 | | 2 | NESTED LOOPS | | 1 | | 500K|00:00:03.52 | 782K| 1 | | 3 | NESTED LOOPS | | 1 | 2 | 500K|00:00:02.00 | 282K| 1 | |* 4 | TABLE ACCESS FULL | T3 | 1 | 7 | 500K|00:00:00.39 | 70498 | 0 | |* 5 | INDEX UNIQUE SCAN | SYS_C0017307 | 500K| 1 | 500K|00:00:00.95 | 212K| 1 | | 6 | TABLE ACCESS BY INDEX ROWID| T1 | 500K| 1 | 500K|00:00:00.86 | 500K| 0 | ----------------------------------------------------------------------------------------------------------------- Peeked Binds (identified by position): -------------------------------------- 1 - (NUMBER): 1 2 - (NUMBER): 10 Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1"="T3"."C1") filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))
To learn more about DBMS_XPLAN.DISPLAY_CURSOR, see the documentation.
So, what if we want to know why the child cursors were created? We could do something like this:
DESC V$SQL_SHARED_CURSOR SET LINESIZE 200 SET HEADING ON BREAK ON SQL_ID SKIP 1 SELECT * FROM V$SQL_SHARED_CURSOR WHERE SQL_ID='94bv1jwkzcc38'; SQL_ID ADDRESS CHILD_ADDRESS CHILD_NUMBER USOOSLFEBPISTABDLTBIIRLIOEMUTNFAITDLDBPCSCPTMBMROPMFLPLAFLRLHPB ------------- ---------------- ---------------- ------------ --------------------------------------------------------------- 94bv1jwkzcc38 0000000257BD5498 0000000257E2E5B0 0 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN 0000000257BD5498 0000000257DC8F18 1 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNN 0000000257BD5498 0000000257C8C3F8 2 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNN
The above shows that the child cursors were created because of an optimizer mode mismatch (yes, we changed the OPTIMIZER_MODE). We could also check the bind variable definitions (not needed in this case because we used the undocumented PEEKED_BINDS format parameter with DBMS_XPLAN to see most of this information):
SELECT S.CHILD_NUMBER CN, SBM.* FROM V$SQL_BIND_METADATA SBM, V$SQL S WHERE S.SQL_ID='94bv1jwkzcc38' AND S.CHILD_ADDRESS=SBM.ADDRESS ORDER BY S.CHILD_NUMBER, SBM.POSITION; CN ADDRESS POSITION DATATYPE MAX_LENGTH ARRAY_LEN BIND_NAME -- ---------------- ---------- ---------- ---------- ---------- --------- 0 0000000257E2E5B0 1 2 22 0 N1 0 0000000257E2E5B0 2 2 22 0 N2 1 0000000257DC8F18 1 2 22 0 N1 1 0000000257DC8F18 2 2 22 0 N2 2 0000000257C8C3F8 1 2 22 0 N1 2 0000000257C8C3F8 2 2 22 0 N2
OK, now that we have moved off on a tangent, let’s return again to the topic of viewing execution plans. The above examples show the actual execution plan that was used, which may be different from that produced by explain plan. So, for fun, let’s look at the EXPLAIN PLAN FOR syntax (DBMS_XPLAN.DISPLAY is valid on Oracle 9.2.0.1 and higher):
ALTER SYSTEM FLUSH SHARED_POOL; ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS'; EXPLAIN PLAN FOR SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN 1 AND 10; Explained. SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY()); Plan hash value: 985299768 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 9 | 2394 | 10219 (1)| 00:02:03 | |* 1 | HASH JOIN | | 9 | 2394 | 10219 (1)| 00:02:03 | |* 2 | TABLE ACCESS FULL | T3 | 10 | 50 | 10214 (1)| 00:02:03 | | 3 | TABLE ACCESS BY INDEX ROWID| T1 | 10 | 2610 | 4 (0)| 00:00:01 | |* 4 | INDEX RANGE SCAN | SYS_C0017307 | 10 | | 3 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - access("T1"."C1"="T3"."C1") 2 - filter("T3"."C1"<=10 AND "T3"."C1">=1) 4 - access("T1"."C1">=1 AND "T1"."C1"<=10)
The above plan appears to be identical to that of the first of the actual plans. Now a test with bind variables:
VARIABLE N1 NUMBER VARIABLE N2 NUMBER EXEC :N1:=1 EXEC :N2:=10 EXPLAIN PLAN FOR SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; Explained. SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY()); Plan hash value: 744086632 ---------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ---------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 1 | FILTER | | | | | | |* 2 | HASH JOIN | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 3 | TABLE ACCESS FULL | T3 | 2500 | 12500 | 10219 (1)| 00:02:03 | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 2500 | 637K| 178 (0)| 00:00:03 | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 4500 | | 11 (0)| 00:00:01 | ---------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2)) 2 - access("T1"."C1"="T3"."C1") 3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2)) 5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
Notice in the above that there are TO_NUMBER entries surrounding each of the bind variables in the Predicate Information section, even though those bind variables were declared as a NUMBER data type. The cost has also increased a bit, and the estimated number of rows jumped from 9 to 2499 (bind peeking did not take place).
Let’s use AUTOTRACE to see the execution plan (AUTOTRACE starting in Oracle 10.1.0.1 uses DBMS_XPLAN to output the formatted execution plan).
SET AUTOTRACE TRACEONLY EXPLAIN SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; Plan hash value: 744086632 ---------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ---------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 1 | FILTER | | | | | | |* 2 | HASH JOIN | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 3 | TABLE ACCESS FULL | T3 | 2500 | 12500 | 10219 (1)| 00:02:03 | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 2500 | 637K| 178 (0)| 00:00:03 | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 4500 | | 11 (0)| 00:00:01 | ---------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2)) 2 - access("T1"."C1"="T3"."C1") 3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2)) 5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
OK, the same as the previous example on Oracle 10.1.0.1 and above, complete with the incorrect Predicate Information section. Again, displaying the runtime statistics and explain plan:
SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN SELECT T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; 10 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 744086632 ---------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ---------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 1 | FILTER | | | | | | |* 2 | HASH JOIN | | 2499 | 649K| 10397 (1)| 00:02:05 | |* 3 | TABLE ACCESS FULL | T3 | 2500 | 12500 | 10219 (1)| 00:02:03 | | 4 | TABLE ACCESS BY INDEX ROWID| T1 | 2500 | 637K| 178 (0)| 00:00:03 | |* 5 | INDEX RANGE SCAN | SYS_C0017307 | 4500 | | 11 (0)| 00:00:01 | ---------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2)) 2 - access("T1"."C1"="T3"."C1") 3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2)) 5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2)) Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 37170 consistent gets 7760 physical reads 0 redo size 812 bytes sent via SQL*Net to client 523 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 10 rows processed
Note that the above plan is not necessarily the actual plan, even though we are looking at the actual runtime statistics. This could be confusing since we are seeing a rough guess for an execution plan with the actual execution statistics.
For more information about Using EXPLAIN PLAN, see the documentation.
Now, another test. This time we will instruct Oracle to write the actual execution plan to a trace file every time Oracle must perform a hard parse. We will force a hard parse by adding a comment to the SQL statement:
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10132_HARD_PARSE'; ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT FOREVER, LEVEL 1'; SELECT /* TEST */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT OFF';
If we take a look at the output in the trace file, we might see something like this:
user_id=68 user_name=TESTUSER module=SQL*Plus action= sql_id=3g3fc5qyju0j3 plan_hash_value=744086632 problem_type=3 ----- Current SQL Statement for this session (sql_id=3g3fc5qyju0j3) ----- SELECT /* TEST */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 sql_text_length=119 sql=SELECT /* TEST */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 ----- Explain Plan Dump ----- ----- Plan Table ----- ============ Plan Table ============ -----------------------------------------------------+-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | -----------------------------------------------------+-----------------------------------+ | 0 | SELECT STATEMENT | | | | 10K | | | 1 | FILTER | | | | | | | 2 | HASH JOIN | | 9 | 2394 | 10K | 00:02:03 | | 3 | TABLE ACCESS FULL | T3 | 10 | 50 | 10K | 00:02:03 | | 4 | TABLE ACCESS BY INDEX ROWID | T1 | 10 | 2610 | 4 | 00:00:01 | | 5 | INDEX RANGE SCAN | SYS_C0017307| 10 | | 3 | 00:00:01 | -----------------------------------------------------+-----------------------------------+ Predicate Information: ---------------------- 1 - filter(:N1<=:N2) 2 - access("T1"."C1"="T3"."C1") 3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1)) 5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2) Content of other_xml column =========================== db_version : 11.2.0.1 parse_schema : TESTUSER plan_hash : 744086632 plan_hash_2 : 3461135235 Peeked Binds ============ Bind variable information position=1 datatype(code)=2 datatype(string)=NUMBER precision=0 scale=0 max length=22 value=1 Bind variable information position=2 datatype(code)=2 datatype(string)=NUMBER precision=0 scale=0 max length=22 value=10 Outline Data: /*+ BEGIN_OUTLINE_DATA IGNORE_OPTIM_EMBEDDED_HINTS OPTIMIZER_FEATURES_ENABLE('11.2.0.1') DB_VERSION('11.2.0.1') ALL_ROWS OUTLINE_LEAF(@"SEL$1") FULL(@"SEL$1" "T3"@"SEL$1") INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C1")) LEADING(@"SEL$1" "T3"@"SEL$1" "T1"@"SEL$1") USE_HASH(@"SEL$1" "T1"@"SEL$1") END_OUTLINE_DATA */ Optimizer state dump: Compilation Environment Dump optimizer_mode_hinted = false optimizer_features_hinted = 0.0.0 parallel_execution_enabled = true parallel_query_forced_dop = 0 parallel_dml_forced_dop = 0 parallel_ddl_forced_degree = 0 parallel_ddl_forced_instances = 0 _query_rewrite_fudge = 90 optimizer_features_enable = 11.2.0.1 _optimizer_search_limit = 5 cpu_count = 8 active_instance_count = 1 hash_area_size = 131072 bitmap_merge_area_size = 1048576 sort_area_size = 65536 sort_area_retained_size = 0 _sort_elimination_cost_ratio = 0 _optimizer_block_size = 8192 _sort_multiblock_read_count = 2 _hash_multiblock_io_count = 0 _db_file_optimizer_read_count = 8 _optimizer_max_permutations = 2000 pga_aggregate_target = 1843200 KB _pga_max_size = 368640 KB _query_rewrite_maxdisjunct = 257 _smm_auto_min_io_size = 56 KB _smm_auto_max_io_size = 248 KB _smm_min_size = 1024 KB _smm_max_size = 184320 KB _smm_px_max_size = 921600 KB _cpu_to_io = 0 _optimizer_undo_cost_change = 11.2.0.1 parallel_query_mode = enabled parallel_dml_mode = disabled parallel_ddl_mode = enabled optimizer_mode = all_rows sqlstat_enabled = false _optimizer_percent_parallel = 101 _always_anti_join = choose _always_semi_join = choose _optimizer_mode_force = true _partition_view_enabled = true _always_star_transformation = false _query_rewrite_or_error = false _hash_join_enabled = true cursor_sharing = exact _b_tree_bitmap_plans = true star_transformation_enabled = false _optimizer_cost_model = choose _new_sort_cost_estimate = true _complex_view_merging = true _unnest_subquery = true _eliminate_common_subexpr = true _pred_move_around = true _convert_set_to_join = false _push_join_predicate = true _push_join_union_view = true _fast_full_scan_enabled = true _optim_enhance_nnull_detection = true _parallel_broadcast_enabled = true _px_broadcast_fudge_factor = 100 _ordered_nested_loop = true _no_or_expansion = false optimizer_index_cost_adj = 100 optimizer_index_caching = 0 _system_index_caching = 0 _disable_datalayer_sampling = false query_rewrite_enabled = true query_rewrite_integrity = enforced _query_cost_rewrite = true _query_rewrite_2 = true _query_rewrite_1 = true _query_rewrite_expression = true _query_rewrite_jgmigrate = true _query_rewrite_fpc = true _query_rewrite_drj = true _full_pwise_join_enabled = true _partial_pwise_join_enabled = true _left_nested_loops_random = true _improved_row_length_enabled = true _index_join_enabled = true _enable_type_dep_selectivity = true _improved_outerjoin_card = true _optimizer_adjust_for_nulls = true _optimizer_degree = 0 _use_column_stats_for_function = true _subquery_pruning_enabled = true _subquery_pruning_mv_enabled = false _or_expand_nvl_predicate = true _like_with_bind_as_equality = false _table_scan_cost_plus_one = true _cost_equality_semi_join = true _default_non_equality_sel_check = true _new_initial_join_orders = true _oneside_colstat_for_equijoins = true _optim_peek_user_binds = true _minimal_stats_aggregation = true _force_temptables_for_gsets = false workarea_size_policy = auto _smm_auto_cost_enabled = true _gs_anti_semi_join_allowed = true _optim_new_default_join_sel = true optimizer_dynamic_sampling = 2 _pre_rewrite_push_pred = true _optimizer_new_join_card_computation = true _union_rewrite_for_gs = yes_gset_mvs _generalized_pruning_enabled = true _optim_adjust_for_part_skews = true _force_datefold_trunc = false statistics_level = typical _optimizer_system_stats_usage = true skip_unusable_indexes = true _remove_aggr_subquery = true _optimizer_push_down_distinct = 0 _dml_monitoring_enabled = true _optimizer_undo_changes = false _predicate_elimination_enabled = true _nested_loop_fudge = 100 _project_view_columns = true _local_communication_costing_enabled = true _local_communication_ratio = 50 _query_rewrite_vop_cleanup = true _slave_mapping_enabled = true _optimizer_cost_based_transformation = linear _optimizer_mjc_enabled = true _right_outer_hash_enable = true _spr_push_pred_refspr = true _optimizer_cache_stats = false _optimizer_cbqt_factor = 50 _optimizer_squ_bottomup = true _fic_area_size = 131072 _optimizer_skip_scan_enabled = true _optimizer_cost_filter_pred = false _optimizer_sortmerge_join_enabled = true _optimizer_join_sel_sanity_check = true _mmv_query_rewrite_enabled = true _bt_mmv_query_rewrite_enabled = true _add_stale_mv_to_dependency_list = true _distinct_view_unnesting = false _optimizer_dim_subq_join_sel = true _optimizer_disable_strans_sanity_checks = 0 _optimizer_compute_index_stats = true _push_join_union_view2 = true _optimizer_ignore_hints = false _optimizer_random_plan = 0 _query_rewrite_setopgrw_enable = true _optimizer_correct_sq_selectivity = true _disable_function_based_index = false _optimizer_join_order_control = 3 _optimizer_cartesian_enabled = true _optimizer_starplan_enabled = true _extended_pruning_enabled = true _optimizer_push_pred_cost_based = true _optimizer_null_aware_antijoin = true _optimizer_extend_jppd_view_types = true _sql_model_unfold_forloops = run_time _enable_dml_lock_escalation = false _bloom_filter_enabled = true _update_bji_ipdml_enabled = 0 _optimizer_extended_cursor_sharing = udo _dm_max_shared_pool_pct = 1 _optimizer_cost_hjsmj_multimatch = true _optimizer_transitivity_retain = true _px_pwg_enabled = true optimizer_secure_view_merging = true _optimizer_join_elimination_enabled = true flashback_table_rpi = non_fbt _optimizer_cbqt_no_size_restriction = true _optimizer_enhanced_filter_push = true _optimizer_filter_pred_pullup = true _rowsrc_trace_level = 0 _simple_view_merging = true _optimizer_rownum_pred_based_fkr = true _optimizer_better_inlist_costing = all _optimizer_self_induced_cache_cost = false _optimizer_min_cache_blocks = 10 _optimizer_or_expansion = depth _optimizer_order_by_elimination_enabled = true _optimizer_outer_to_anti_enabled = true _selfjoin_mv_duplicates = true _dimension_skip_null = true _force_rewrite_enable = false _optimizer_star_tran_in_with_clause = true _optimizer_complex_pred_selectivity = true _optimizer_connect_by_cost_based = true _gby_hash_aggregation_enabled = true _globalindex_pnum_filter_enabled = true _px_minus_intersect = true _fix_control_key = 0 _force_slave_mapping_intra_part_loads = false _force_tmp_segment_loads = false _query_mmvrewrite_maxpreds = 10 _query_mmvrewrite_maxintervals = 5 _query_mmvrewrite_maxinlists = 5 _query_mmvrewrite_maxdmaps = 10 _query_mmvrewrite_maxcmaps = 20 _query_mmvrewrite_maxregperm = 512 _query_mmvrewrite_maxmergedcmaps = 50 _query_mmvrewrite_maxqryinlistvals = 500 _disable_parallel_conventional_load = false _trace_virtual_columns = false _replace_virtual_columns = true _virtual_column_overload_allowed = true _kdt_buffering = true _first_k_rows_dynamic_proration = true _optimizer_sortmerge_join_inequality = true _optimizer_aw_stats_enabled = true _bloom_pruning_enabled = true result_cache_mode = MANUAL _px_ual_serial_input = true _optimizer_skip_scan_guess = false _enable_row_shipping = true _row_shipping_threshold = 80 _row_shipping_explain = false transaction_isolation_level = read_commited _optimizer_distinct_elimination = true _optimizer_multi_level_push_pred = true _optimizer_group_by_placement = true _optimizer_rownum_bind_default = 10 _enable_query_rewrite_on_remote_objs = true _optimizer_extended_cursor_sharing_rel = simple _optimizer_adaptive_cursor_sharing = true _direct_path_insert_features = 0 _optimizer_improve_selectivity = true optimizer_use_pending_statistics = false _optimizer_enable_density_improvements = true _optimizer_aw_join_push_enabled = true _optimizer_connect_by_combine_sw = true _enable_pmo_ctas = 0 _optimizer_native_full_outer_join = force _bloom_predicate_enabled = true _optimizer_enable_extended_stats = true _is_lock_table_for_ddl_wait_lock = 0 _pivot_implementation_method = choose optimizer_capture_sql_plan_baselines = false optimizer_use_sql_plan_baselines = true _optimizer_star_trans_min_cost = 0 _optimizer_star_trans_min_ratio = 0 _with_subquery = OPTIMIZER _optimizer_fkr_index_cost_bias = 10 _optimizer_use_subheap = true parallel_degree_policy = manual parallel_degree = 0 parallel_min_time_threshold = 10 _parallel_time_unit = 10 _optimizer_or_expansion_subheap = true _optimizer_free_transformation_heap = true _optimizer_reuse_cost_annotations = true _result_cache_auto_size_threshold = 100 _result_cache_auto_time_threshold = 1000 _optimizer_nested_rollup_for_gset = 100 _nlj_batching_enabled = 1 parallel_query_default_dop = 0 is_recur_flags = 0 optimizer_use_invisible_indexes = false flashback_data_archive_internal_cursor = 0 _optimizer_extended_stats_usage_control = 224 _parallel_syspls_obey_force = true cell_offload_processing = true _rdbms_internal_fplib_enabled = false db_file_multiblock_read_count = 128 _bloom_folding_enabled = true _mv_generalized_oj_refresh_opt = true cell_offload_compaction = ADAPTIVE parallel_degree_limit = 65535 parallel_force_local = false parallel_max_degree = 16 total_cpu_count = 8 cell_offload_plan_display = AUTO _optimizer_coalesce_subqueries = true _optimizer_fast_pred_transitivity = true _optimizer_fast_access_pred_analysis = true _optimizer_unnest_disjunctive_subq = true _optimizer_unnest_corr_set_subq = true _optimizer_distinct_agg_transform = true _aggregation_optimization_settings = 0 _optimizer_connect_by_elim_dups = true _optimizer_eliminate_filtering_join = true _connect_by_use_union_all = true dst_upgrade_insert_conv = true advanced_queuing_internal_cursor = 0 _optimizer_unnest_all_subqueries = true _bloom_predicate_pushdown_to_storage = true _bloom_vector_elements = 0 _bloom_pushing_max = 524288 parallel_autodop = 0 parallel_ddldml = 0 _parallel_cluster_cache_policy = adaptive _parallel_scalability = 50 iot_internal_cursor = 0 _optimizer_instance_count = 0 _optimizer_connect_by_cb_whr_only = false _suppress_scn_chk_for_cqn = nosuppress_1466 _optimizer_join_factorization = true _optimizer_use_cbqt_star_transformation = true _optimizer_table_expansion = true _and_pruning_enabled = true _deferred_constant_folding_mode = DEFAULT _optimizer_distinct_placement = true partition_pruning_internal_cursor = 0 parallel_hinted = none _sql_compatibility = 0 _optimizer_use_feedback = true _optimizer_try_st_before_jppd = true Bug Fix Control Environment fix 3834770 = 1 fix 3746511 = enabled fix 4519016 = enabled fix 3118776 = enabled fix 4488689 = enabled fix 2194204 = disabled fix 2660592 = enabled fix 2320291 = enabled fix 2324795 = enabled fix 4308414 = enabled fix 3499674 = disabled fix 4569940 = enabled fix 4631959 = enabled fix 4519340 = enabled fix 4550003 = enabled fix 1403283 = enabled fix 4554846 = enabled fix 4602374 = enabled fix 4584065 = enabled fix 4545833 = enabled fix 4611850 = enabled fix 4663698 = enabled fix 4663804 = enabled fix 4666174 = enabled fix 4567767 = enabled fix 4556762 = 15 fix 4728348 = enabled fix 4708389 = enabled fix 4175830 = enabled fix 4752814 = enabled fix 4583239 = enabled fix 4386734 = enabled fix 4887636 = enabled fix 4483240 = enabled fix 4872602 = disabled fix 4711525 = enabled fix 4545802 = enabled fix 4605810 = enabled fix 4704779 = enabled fix 4900129 = enabled fix 4924149 = enabled fix 4663702 = enabled fix 4878299 = enabled fix 4658342 = enabled fix 4881533 = enabled fix 4676955 = enabled fix 4273361 = enabled fix 4967068 = enabled fix 4969880 = disabled fix 5005866 = enabled fix 5015557 = enabled fix 4705343 = enabled fix 4904838 = enabled fix 4716096 = enabled fix 4483286 = disabled fix 4722900 = enabled fix 4615392 = enabled fix 5096560 = enabled fix 5029464 = enabled fix 4134994 = enabled fix 4904890 = enabled fix 5104624 = enabled fix 5014836 = enabled fix 4768040 = enabled fix 4600710 = enabled fix 5129233 = enabled fix 4595987 = enabled fix 4908162 = enabled fix 5139520 = enabled fix 5084239 = enabled fix 5143477 = disabled fix 2663857 = enabled fix 4717546 = enabled fix 5240264 = disabled fix 5099909 = enabled fix 5240607 = enabled fix 5195882 = enabled fix 5220356 = enabled fix 5263572 = enabled fix 5385629 = enabled fix 5302124 = enabled fix 5391942 = enabled fix 5384335 = enabled fix 5482831 = enabled fix 4158812 = enabled fix 5387148 = enabled fix 5383891 = enabled fix 5466973 = enabled fix 5396162 = enabled fix 5394888 = enabled fix 5395291 = enabled fix 5236908 = enabled fix 5509293 = enabled fix 5449488 = enabled fix 5567933 = enabled fix 5570494 = enabled fix 5288623 = enabled fix 5505995 = enabled fix 5505157 = enabled fix 5112460 = enabled fix 5554865 = enabled fix 5112260 = enabled fix 5112352 = enabled fix 5547058 = enabled fix 5618040 = enabled fix 5585313 = enabled fix 5547895 = enabled fix 5634346 = enabled fix 5620485 = enabled fix 5483301 = enabled fix 5657044 = enabled fix 5694984 = enabled fix 5868490 = enabled fix 5650477 = enabled fix 5611962 = enabled fix 4279274 = enabled fix 5741121 = enabled fix 5714944 = enabled fix 5391505 = enabled fix 5762598 = enabled fix 5578791 = enabled fix 5259048 = enabled fix 5882954 = enabled fix 2492766 = enabled fix 5707608 = enabled fix 5891471 = enabled fix 5884780 = enabled fix 5680702 = enabled fix 5371452 = enabled fix 5838613 = enabled fix 5949981 = enabled fix 5624216 = enabled fix 5741044 = enabled fix 5976822 = enabled fix 6006457 = enabled fix 5872956 = enabled fix 5923644 = enabled fix 5943234 = enabled fix 5844495 = enabled fix 4168080 = enabled fix 6020579 = enabled fix 5842686 = disabled fix 5996801 = enabled fix 5593639 = enabled fix 6133948 = enabled fix 3151991 = enabled fix 6146906 = enabled fix 6239909 = enabled fix 6267621 = enabled fix 5909305 = enabled fix 6279918 = enabled fix 6141818 = enabled fix 6151963 = enabled fix 6251917 = enabled fix 6282093 = enabled fix 6119510 = enabled fix 6119382 = enabled fix 3801750 = enabled fix 5705630 = disabled fix 5944076 = enabled fix 5406763 = enabled fix 6070954 = enabled fix 6282944 = enabled fix 6138746 = enabled fix 6082745 = enabled fix 3426050 = enabled fix 599680 = enabled fix 6062266 = enabled fix 6087237 = enabled fix 6122894 = enabled fix 6377505 = enabled fix 5893768 = enabled fix 6163564 = enabled fix 6073325 = enabled fix 6188881 = enabled fix 6007259 = enabled fix 6239971 = enabled fix 5284200 = disabled fix 6042205 = enabled fix 6051211 = enabled fix 6434668 = enabled fix 6438752 = enabled fix 5936366 = enabled fix 6439032 = enabled fix 6438892 = enabled fix 6006300 = enabled fix 5947231 = enabled fix 5416118 = 1 fix 6365442 = 1 fix 6239039 = enabled fix 6502845 = enabled fix 6913094 = enabled fix 6029469 = enabled fix 5919513 = enabled fix 6057611 = enabled fix 6469667 = enabled fix 6608941 = disabled fix 6368066 = enabled fix 6329318 = enabled fix 6656356 = enabled fix 4507997 = enabled fix 6671155 = enabled fix 6694548 = enabled fix 6688200 = enabled fix 6612471 = enabled fix 6708183 = disabled fix 6326934 = enabled fix 6520717 = disabled fix 6714199 = enabled fix 6681545 = enabled fix 6748058 = enabled fix 6167716 = enabled fix 6674254 = enabled fix 6468287 = enabled fix 6503543 = enabled fix 6808773 = disabled fix 6766962 = enabled fix 6120483 = enabled fix 6670551 = enabled fix 6771838 = enabled fix 6626018 = disabled fix 6530596 = enabled fix 6778642 = enabled fix 6699059 = enabled fix 6376551 = enabled fix 6429113 = enabled fix 6782437 = enabled fix 6776808 = enabled fix 6765823 = enabled fix 6768660 = enabled fix 6782665 = enabled fix 6610822 = enabled fix 6514189 = enabled fix 6818410 = enabled fix 6827696 = enabled fix 6773613 = enabled fix 5902962 = enabled fix 6956212 = enabled fix 3056297 = enabled fix 6440977 = disabled fix 6972291 = disabled fix 6904146 = enabled fix 6221403 = enabled fix 5475051 = enabled fix 6845871 = enabled fix 5468809 = enabled fix 6917633 = enabled fix 4444536 = disabled fix 6955210 = enabled fix 6994194 = enabled fix 6399597 = disabled fix 6951776 = enabled fix 5648287 = 3 fix 6987082 = disabled fix 7132036 = enabled fix 6980350 = enabled fix 5199213 = enabled fix 7138405 = enabled fix 7148689 = enabled fix 6820988 = enabled fix 7032684 = enabled fix 6617866 = enabled fix 7155968 = enabled fix 7127980 = enabled fix 6982954 = enabled fix 7241819 = enabled fix 6897034 = enabled fix 7236148 = enabled fix 7298570 = enabled fix 7249095 = enabled fix 7314499 = enabled fix 7324224 = enabled fix 7289023 = enabled fix 7237571 = enabled fix 7116357 = enabled fix 7345484 = enabled fix 7375179 = enabled fix 6430500 = disabled fix 5897486 = enabled fix 6774209 = enabled fix 7306637 = enabled fix 6451322 = enabled fix 7208131 = enabled fix 7388652 = enabled fix 7127530 = enabled fix 6751206 = enabled fix 6669103 = enabled fix 7430474 = enabled fix 6990305 = enabled fix 7043307 = enabled fix 6921505 = enabled fix 7388457 = enabled fix 3120429 = enabled fix 7452823 = disabled fix 6838105 = enabled fix 6769711 = enabled fix 7170213 = enabled fix 6528872 = enabled fix 7295298 = enabled fix 5922070 = enabled fix 7259468 = enabled fix 6418552 = enabled fix 4619997 = enabled fix 7524366 = enabled fix 6942476 = enabled fix 6418771 = enabled fix 7375077 = enabled fix 5400639 = enabled fix 4570921 = enabled fix 7426911 = enabled fix 5099019 = disabled fix 7528216 = enabled fix 7521266 = enabled fix 7385140 = enabled fix 7576516 = enabled fix 7573526 = enabled fix 7576476 = enabled fix 7165898 = enabled fix 7263214 = enabled fix 3320140 = enabled fix 7555510 = enabled fix 7613118 = enabled fix 7597059 = enabled fix 7558911 = enabled fix 5520732 = enabled fix 7679490 = disabled fix 7449971 = enabled fix 3628118 = enabled fix 4370840 = enabled fix 7281191 = enabled fix 7519687 = enabled fix 5029592 = 3 fix 6012093 = 1 fix 6053861 = disabled fix 6941515 = disabled fix 7696414 = enabled fix 7272039 = enabled fix 7834811 = enabled fix 7640597 = enabled fix 7341616 = enabled fix 7168184 = enabled fix 399198 = enabled fix 7831070 = enabled fix 7676897 = disabled fix 7414637 = enabled fix 7585456 = enabled fix 8202421 = enabled fix 7658097 = disabled fix 8251486 = enabled fix 7132684 = enabled fix 7512227 = enabled fix 6972987 = enabled fix 7199035 = enabled fix 8243446 = enabled fix 7650462 = enabled fix 6720701 = enabled fix 7592673 = enabled fix 7718694 = enabled fix 7534027 = enabled fix 7708267 = enabled fix 5716785 = enabled fix 7356191 = enabled fix 7679161 = enabled fix 7597159 = enabled fix 7499258 = enabled fix 8328363 = enabled fix 7452863 = enabled fix 8284930 = enabled fix 7298626 = enabled fix 7657126 = enabled fix 8371884 = enabled fix 8318020 = enabled fix 8255423 = enabled fix 7135745 = enabled fix 8356253 = enabled fix 7534257 = enabled fix 8323407 = enabled fix 7539815 = enabled fix 8289316 = enabled fix 8447850 = enabled fix 7675944 = enabled fix 8355120 = enabled fix 7176746 = enabled fix 8442891 = enabled fix 8373261 = enabled fix 7679164 = enabled fix 7670533 = enabled fix 8408665 = enabled fix 8491399 = enabled fix 8348392 = enabled fix 8348585 = enabled fix 8508056 = enabled fix 8335178 = enabled fix 8515269 = enabled fix 8247017 = enabled fix 7325597 = enabled fix 8531490 = enabled fix 6163600 = enabled fix 8589278 = disabled fix 8557992 = enabled fix 7556098 = enabled fix 8580883 = enabled fix 5892599 = disabled fix 8609714 = enabled fix 8514561 = enabled fix 8619631 = disabled Query Block Registry: SEL$1 0x6e975eb0 (PARSER) [FINAL] : call(in-use=25024, alloc=82024), compile(in-use=102048, alloc=164272), execution(in-use=12872, alloc=16200) End of Optimizer State Dump Dumping Hints =============
Note in the above that we are able to see the actual execution plan, the peeked bind variables, the set of hints that will reproduce the execution plan, and a large number of normal and hidden optimizer parameters. Comparing the output with that of Oracle Database 10.2.0.2, you will notice that server additional parameters are listed in the output.
An example with a 10046 trace at level 4 (by default, on Oracle 11.1.0.6 and higher we no longer need to execute another SQL statement after the SQL statement under investigation so that the STAT lines for our SQL statement are written to the trace file):
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_EXECUTION_PLAN'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4'; SELECT /* TEST */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT SYSDATE FROM DUAL;
The resulting trace file looks something like this (you did read Chapter 15 of the book, didn’t you – so be sure to delete the trace files when no longer needed):
===================== PARSING IN CURSOR #6 len=118 dep=0 uid=68 oct=3 lid=68 tim=1264989049019258 hv=3172794915 ad='25b889600' sqlid='3g3fc5qyju0j3' SELECT /* TEST */ T3.C1, SUBSTR(T1.C2,1,10) C2 FROM T3, T1 WHERE T1.C1=T3.C1 AND T1.C1 BETWEEN :N1 AND :N2 END OF STMT PARSE #6:c=0,e=165,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1264989049019257 BINDS #6: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0 kxsbbbfp=2b7f6eb34ea8 bln=22 avl=02 flg=05 value=1 Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24 kxsbbbfp=2b7f6eb34ec0 bln=22 avl=02 flg=01 value=10 EXEC #6:c=999,e=1078,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=744086632,tim=1264989049020428 FETCH #6:c=74988,e=75221,p=0,cr=37168,cu=0,mis=0,r=1,dep=0,og=1,plh=744086632,tim=1264989049095700 FETCH #6:c=0,e=50,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=744086632,tim=1264989049095954 STAT #6 id=1 cnt=10 pid=0 pos=1 obj=0 op='FILTER (cr=37170 pr=0 pw=0 time=0 us)' STAT #6 id=2 cnt=10 pid=1 pos=1 obj=0 op='HASH JOIN (cr=37170 pr=0 pw=0 time=0 us cost=10219 size=2394 card=9)' STAT #6 id=3 cnt=10 pid=2 pos=1 obj=70288 op='TABLE ACCESS FULL T3 (cr=37164 pr=0 pw=0 time=0 us cost=10214 size=50 card=10)' STAT #6 id=4 cnt=10 pid=2 pos=2 obj=70284 op='TABLE ACCESS BY INDEX ROWID T1 (cr=6 pr=0 pw=0 time=0 us cost=4 size=2610 card=10)' STAT #6 id=5 cnt=10 pid=4 pos=1 obj=70285 op='INDEX RANGE SCAN SYS_C0017307 (cr=4 pr=0 pw=0 time=36 us cost=3 size=0 card=10)' CLOSE #6:c=0,e=10,dep=0,type=0,tim=1264989049096413 =====================
If you compare the above output with that of Oracle 10.2.0.2, you will notice that the SQL_ID for the SQL statement is written to the trace file, the STAT lines include cardinality estimates, and when a cursor is closed a line is written to the trace file. We could, of course, just read the actual plan direct from the 10046 trace file, as well as the bind variable values and data types. But, we will use TKPROF instead (we will not be able to see the bind variable values when using TKPROF).
> tkprof or112_ora_5062_10046_EXECUTION_PLAN.trc or112_ora_5062_10046_EXECUTION_PLAN.txt
The output might look like this:
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.07 0.07 0 37170 0 10 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.07 0.07 0 37170 0 10 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 68 Rows Row Source Operation ------- --------------------------------------------------- 10 FILTER (cr=37170 pr=0 pw=0 time=0 us) 10 HASH JOIN (cr=37170 pr=0 pw=0 time=0 us cost=10219 size=2394 card=9) 10 TABLE ACCESS FULL T3 (cr=37164 pr=0 pw=0 time=0 us cost=10214 size=50 card=10) 10 TABLE ACCESS BY INDEX ROWID T1 (cr=6 pr=0 pw=0 time=0 us cost=4 size=2610 card=10) 10 INDEX RANGE SCAN SYS_C0017307 (cr=4 pr=0 pw=0 time=36 us cost=3 size=0 card=10)(object id 70285)
What else has changed? Nested – Nested Loops joins… interesting.
[…] It? Charles Hooper-Execution Plans – What is the Plan, and Where Do I Find It 2? Charles Hooper-Execution Plans – What is the Plan, and Where Do I Find It 3? 20-Faulty quotes about %100 CPU utilization ? (comments) Charles Hooper-Faulty Quotes 6 – CPU […]