Striving for Optimal Performance

While writing a post about the TKPROF new features in 11.2.0.2 I noticed that I didn’t write one about an important change introduced in 11.2.0.1. So, before finishing the other one, let’s have a look to what changed in 11.2.0.1.

One problem with TKPROF up to 11gR1 is that when the AGGREGATE parameter is set to YES (which is the default), all information belonging to cursors having the same text is aggregated in a single SQL statement. This is fine when all cursors were executed with the same execution plan. However, this is also done when a cursor was executed with several execution plans. As a result, only one execution plan is visible in the output. The others are lost.

As of 11gR2 this problem is solved. In fact, every SQL statement in the output is only related to a single execution plan.

To illustrate this enhancement let’s have a look to the TKPROF output for the trace file generated by the following commands (the test table is the one of the SH sample schema):

VARIABLE channel_id NUMBER
EXECUTE dbms_monitor.session_trace_enable(plan_stat=>'all_executions', waits=>false)
EXECUTE :channel_id := 2;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 3;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 4;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 5;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 9;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE dbms_monitor.session_trace_disable
SELECT value FROM v$diag_info WHERE name = 'Default Trace File';

The essential thing to know about the query used in this test is that the selectivity strongly depends on the value of the CHANNEL_ID variable. The following query shows the actual distribution:

SQL> SELECT channel_id, count(*)
  2  FROM sh.sales
  3  GROUP BY channel_id
  4  ORDER BY channel_id;

CHANNEL_ID   COUNT(*)
---------- ----------
         2     258025
         3     540328
         4     118416
         9       2074

Hence, when running the commands shown above, two execution plans are expected.

• When the selectivity is weak (high), the execution plan should be based on a full table scan.
• When the selectivity is strong (low), the execution plan should be based on an index range scan.

After generating the trace file with 11gR2, let’s have a look to the output provided by TKPROF.

• 11.1.0.7

SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.04       0.03          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch    61263      2.95       2.99          0      66150          0      918843
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61273      3.01       3.03          0      66150          0      918843

Misses in library cache during parse: 1
Misses in library cache during execute: 3
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)

• 11.2.0.1

SQL ID: 94mzsr37n3vz0
Plan Hash: 1550251865
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.04       0.03          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch    61122      2.94       2.98          0      65918          0      916769
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61128      2.99       3.02          0      65918          0      916769

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)

SQL ID: 94mzsr37n3vz0
Plan Hash: 3721375305
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch      141      0.00       0.00          0        232          0        2074
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      145      0.01       0.01          0        232          0        2074

Misses in library cache during parse: 0
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
   2074  PARTITION RANGE ALL PARTITION: 1 28 (cr=200 pr=0 pw=0 time=4602 us cost=325 size=78184 card=2696)
   2074   TABLE ACCESS BY LOCAL INDEX ROWID SALES PARTITION: 1 28 (cr=200 pr=0 pw=0 time=3979 us cost=325 size=78184 card=2696)
   2074    BITMAP CONVERSION TO ROWIDS (cr=32 pr=0 pw=0 time=993 us)
      3     BITMAP INDEX SINGLE VALUE SALES_CHANNEL_BIX PARTITION: 1 28 (cr=32 pr=0 pw=0 time=189 us)(object id 13980)

As you can see, in the 11.1.0.7 output the 5 executions are associated to a single SQL statement. So, according to it, it is sensible to say that all 5 executions used the same execution plan based on a full table scan. However, as described above, this is not true. The 11.2.0.1 output doesn’t exhibit the same problem. In fact, the information is separated in two SQL statements. For that reason the section providing the information about a SQL statement begins with the information not only about the SQL ID, but also about the hash value of the execution plan. Note that the SQL ID is missing from the 11.1.0.7 output. No idea why… In fact, in 11.1.0.6, it is present. The hash value, however, was added in 11gR2.

Even though in general parallel full table scans performs direct reads, some exceptions exist. The aim of this post is to show such an exception.

For test purposes I build in my own schema a copy of the SH.SALES table (the one distributed by Oracle with the demo schemas…). On that table I build an index on the TIME_ID column and, at the same time, I trace the execution. The statements I use are the following.

execute dbms_monitor.session_trace_enable
CREATE INDEX sales_time_id ON sales (time_id) PARALLEL 2 ONLINE;
execute dbms_monitor.session_trace_disable

Since the index is built in parallel (DOP=2), 5 processes are used to run the statement: the query coordinator, 2 slaves for reading the table, and 2 slaves for building the index. Based on the data provided by extended SQL trace let’s have a look to some information about the execution.

• Execution plan (without runtime statistics and query optimizer estimations): both the build of the index and the full table scan are performed in parallel.

Operation
----------------------------------------
PX COORDINATOR
  PX SEND QC (ORDER) :TQ10001
    INDEX BUILD NON UNIQUE SALES_TIME_ID
      SORT CREATE INDEX
        PX RECEIVE
          PX SEND RANGE :TQ10000
            PX BLOCK ITERATOR
              TABLE ACCESS FULL SALES

• Resource usage profile of the query coordinator: no real work is performed, it’s just coordination work…

                                               Total            Number of     Duration per
Component                               Duration [s]       %       Events       Events [s]
----------------------------------- ---------------- ------- ------------ ----------------
PX Deq: Execute Reply                          1.928  79.044           44            0.044
recursive statements                           0.427  17.487          n/a              n/a
CPU                                            0.024   0.984          n/a              n/a
os thread startup                              0.017   0.690            1            0.017
log file sync                                  0.014   0.569            2            0.007
PX Deq: Parse Reply                            0.014   0.568            4            0.003
enq: CR - block range reuse ckpt               0.005   0.202            2            0.002
PX Deq: Join ACK                               0.004   0.145            5            0.001
SQL*Net message from client                    0.002   0.098            1            0.002
PX qref latch                                  0.002   0.075            1            0.002
PX Deq: Table Q qref                           0.001   0.058            1            0.001
enq: RO - fast object reuse                    0.001   0.028            1            0.001
PX Deq: Signal ACK EXT                         0.001   0.025            6            0.000
PX Deq: Slave Session Stats                    0.000   0.014            3            0.000
reliable message                               0.000   0.006            2            0.000
latch: call allocation                         0.000   0.004            1            0.000
db file sequential read                        0.000   0.004            6            0.000
rdbms ipc reply                                0.000   0.002            2            0.000
SQL*Net message to client                      0.000   0.000            1            0.000
----------------------------------- ---------------- -------
Total                                          2.439 100.000

• Resource usage profile of one of the slaves building the index: direct writes are used to store the index.

                                               Total            Number of     Duration per
Component                               Duration [s]       %       Events       Events [s]
----------------------------------- ---------------- ------- ------------ ----------------
direct path write                              0.982  49.671          376            0.003
CPU                                            0.781  39.508          n/a              n/a
PX Deq: Table Q Normal                         0.177   8.957          130            0.001
PX Deq: Execution Msg                          0.012   0.595            4            0.003
cursor: pin S wait on X                        0.011   0.535            1            0.011
recursive statements                           0.008   0.420          n/a              n/a
log file sync                                  0.005   0.247            3            0.002
Disk file operations I/O                       0.001   0.030            1            0.001
PX Deq: Slave Session Stats                    0.000   0.021            1            0.000
reliable message                               0.000   0.011            1            0.000
rdbms ipc reply                                0.000   0.006            2            0.000
----------------------------------- ---------------- -------
Total                                          1.977 100.000

• Resource usage profile of one of the slaves scanning the table: instead of performing direct reads, “regular” buffered reads are performed (notice the db file scattered read event).

                                               Total            Number of     Duration per
Component                               Duration [s]       %       Events       Events [s]
----------------------------------- ---------------- ------- ------------ ----------------
PX Deq: Execution Msg                          1.571  80.295           23            0.068
CPU                                            0.311  15.889          n/a              n/a
PX Deq Credit: need buffer                     0.055   2.794          432            0.000
db file scattered read                         0.016   0.835           55            0.000
PX Deq: Table Q Get Keys                       0.002   0.109            1            0.002
Disk file operations I/O                       0.001   0.032            1            0.001
PX Deq Credit: send blkd                       0.001   0.028            1            0.001
PX Deq: Slave Session Stats                    0.000   0.010            1            0.000
db file sequential read                        0.000   0.005            4            0.000
PX qref latch                                  0.000   0.002            1            0.000
latch: cache buffers chains                    0.000   0.000            1            0.000
----------------------------------- ---------------- -------
Total                                          1.957 100.000

As pointed out by the last resource usage profile no direct reads are performed. Why? In this case it is because the ONLINE option was specified. By the way, I do not know why there is such a limitation… Anway, without this option, for one of the slaves reading the table the following resource usage profile is used (notice the direct path read event). I do not show the other resource usage profiles and the execution plan because they do not change.

                                               Total            Number of     Duration per
Component                               Duration [s]       %       Events       Events [s]
----------------------------------- ---------------- ------- ------------ ----------------
PX Deq: Execution Msg                          1.499  80.358           22            0.068
CPU                                            0.278  14.897          n/a              n/a
PX Deq Credit: need buffer                     0.071   3.790          504            0.000
direct path read                               0.012   0.630           52            0.000
PX Deq Credit: send blkd                       0.003   0.176            2            0.002
PX Deq: Table Q Get Keys                       0.001   0.047            2            0.000
PX Deq: Slave Session Stats                    0.001   0.041            1            0.001
Disk file operations I/O                       0.001   0.033            1            0.001
library cache: mutex X                         0.000   0.025            1            0.000
db file sequential read                        0.000   0.002            2            0.000
asynch descriptor resize                       0.000   0.001           18            0.000
----------------------------------- ---------------- -------
Total                                          1.866 100.000

In summary, do not expect to always see direct reads when a parallel full table scan is performed.

When two tables are equi-partitioned on their join keys, the query optimizer is able to take advantage of partition-wise joins. To make sure that the tables are equi-partitioned, as of Oracle Database 11g reference partitioning can be used. In fact, per definition, with reference partitioning all “related” tables have exactly the same partitioning schema. If you are not using reference partitioning, you must be very careful that the tables are effectively partitioned in very same way. For range and hash partitioned tables this is usually not a problem. However, when using list partitioning, it is quite easy to make a mistake. The reason is that the partitions can be defined in any order. Let’s have a look to an example based on the following two tables.

SQL> CREATE TABLE t1p
  2  PARTITION BY LIST (pkey) (
  3    PARTITION p_0 VALUES (0),
  4    PARTITION p_1 VALUES (1),
  5    PARTITION p_2 VALUES (2),
  6    PARTITION p_3 VALUES (3),
  7    PARTITION p_4 VALUES (4),
  8    PARTITION p_5 VALUES (5),
  9    PARTITION p_6 VALUES (6),
 10    PARTITION p_7 VALUES (7),
 11    PARTITION p_8 VALUES (8),
 12    PARTITION p_9 VALUES (9)
 13  )
 14  AS
 15  SELECT rownum AS num, mod(rownum,10) AS pkey, dbms_random.string('p',50) AS pad
 16  FROM dual
 17  CONNECT BY level <= 10000;

SQL> CREATE TABLE t2p
  2  PARTITION BY LIST (pkey) (
  3    PARTITION p_0 VALUES (0),
  4    PARTITION p_1 VALUES (1),
  5    PARTITION p_2 VALUES (2),
  6    PARTITION p_3 VALUES (3),
  7    PARTITION p_5 VALUES (5),
  8    PARTITION p_4 VALUES (4),
  9    PARTITION p_6 VALUES (6),
 10    PARTITION p_7 VALUES (7),
 11    PARTITION p_8 VALUES (8),
 12    PARTITION p_9 VALUES (9)
 13  )
 14  AS
 15  SELECT rownum AS num, mod(rownum,10) AS pkey, dbms_random.string('p',50) AS pad
 16  FROM dual
 17  CONNECT BY level <= 10000;

SQL> BEGIN
  2    dbms_stats.gather_table_stats(user,'t1p');
  3    dbms_stats.gather_table_stats(user,'t2p');
  4  END;
  5  /

Even though they are logically equivalent, as shown in the following execution plan, with them partition-wise joins cannot be used.

SQL> EXPLAIN PLAN FOR SELECT * FROM t1p JOIN t2p USING (num, pkey);

SQL> SELECT * FROM table(dbms_xplan.display(format=>'basic'));

PLAN_TABLE_OUTPUT
------------------------------------

Plan hash value: 3059592055

------------------------------------
| Id  | Operation           | Name |
------------------------------------
|   0 | SELECT STATEMENT    |      |
|   1 |  HASH JOIN          |      |
|   2 |   PARTITION LIST ALL|      |
|   3 |    TABLE ACCESS FULL| T1P  |
|   4 |   PARTITION LIST ALL|      |
|   5 |    TABLE ACCESS FULL| T2P  |
------------------------------------

The difference in the order of the partitions can also be confirmed by a query like the following one.

SQL> SELECT t1p.high_value,
  2         t1p.partition_position AS pos_t1p,
  3         t2p.partition_position AS pos_t2p,
  4         decode(t1p.partition_position, t2p.partition_position, 'Y', 'N') AS equal
  5  FROM user_tab_partitions t1p JOIN user_tab_partitions t2p ON t1p.partition_name = t2p.partition_name
  6  WHERE t1p.table_name = 'T1P'
  7  AND t2p.table_name = 'T2P';

HIGH_VALUE   POS_T1P  POS_T2P EQUAL
----------- -------- -------- ------
0                  1        1 Y
1                  2        2 Y
2                  3        3 Y
3                  4        4 Y
5                  6        5 N
4                  5        6 N
6                  7        7 Y
7                  8        8 Y
8                  9        9 Y
9                 10       10 Y

It goes without saying that to solve the problem it is necessary to reorder the partitions. To do so it is enough to move the out-of-order partitions. To avoid a double storage of the data a series of ALTER TABLE EXCHANGE/DROP/ADD/EXCHANGE statements can be used.

• Move the P5 partition of the T1P table

SQL> CREATE TABLE t1p_5 AS
  2  SELECT *
  3  FROM t1p PARTITION (p_5)
  4  WHERE 1 = 0;

SQL> ALTER TABLE t1p EXCHANGE PARTITION p_5 WITH TABLE t1p_5;

SQL> ALTER TABLE t1p DROP PARTITION p_5;

SQL> ALTER TABLE t1p ADD PARTITION p_5 VALUES (5);

SQL> ALTER TABLE t1p EXCHANGE PARTITION p_5 WITH TABLE t1p_5;

SQL> DROP TABLE t1p_5 PURGE;

• Move the P5 partition of the T2P table

SQL> CREATE TABLE t2p_5 AS
  2  SELECT *
  3  FROM t2p PARTITION (p_5)
  4  WHERE 1 = 0;

SQL> ALTER TABLE t2p EXCHANGE PARTITION p_5 WITH TABLE t2p_5;

SQL> ALTER TABLE t2p DROP PARTITION p_5;

SQL> ALTER TABLE t2p ADD PARTITION p_5 VALUES (5);

SQL> ALTER TABLE t2p EXCHANGE PARTITION p_5 WITH TABLE t2p_5;

SQL> DROP TABLE t2p_5 PURGE;

• Check whether the order is ok

SQL> SELECT t1p.high_value,
  2         t1p.partition_position AS pos_t1p,
  3         t2p.partition_position AS pos_t2p,
  4         decode(t1p.partition_position, t2p.partition_position, 'Y', 'N') AS equal
  5  FROM user_tab_partitions t1p JOIN user_tab_partitions t2p ON t1p.partition_name = t2p.partition_name
  6  WHERE t1p.table_name = 'T1P'
  7  AND t2p.table_name = 'T2P';

HIGH_VALUE   POS_T1P  POS_T2P EQUAL
----------- -------- -------- ------
0                  1        1 Y
1                  2        2 Y
2                  3        3 Y
3                  4        4 Y
4                  5        5 Y
6                  6        6 Y
7                  7        7 Y
8                  8        8 Y
9                  9        9 Y
5                 10       10 Y

After these operations partition-wise joins are allowed. The following execution plan confirms this.

SQL> SELECT * FROM table(dbms_xplan.display(format=>'basic'));

PLAN_TABLE_OUTPUT
------------------------------------

Plan hash value: 1324269388

------------------------------------
| Id  | Operation           | Name |
------------------------------------
|   0 | SELECT STATEMENT    |      |
|   1 |  PARTITION LIST ALL |      |
|   2 |   HASH JOIN         |      |
|   3 |    TABLE ACCESS FULL| T1P  |
|   4 |    TABLE ACCESS FULL| T2P  |
------------------------------------

During an evolution the database engine compares the performance of two execution plans. The aim is to find out which one provides the better performance. For that purpose it has to run the SQL statement on which the SQL plan baseline is based and compare some execution statistics. The following output of the DBMS_SPM.EVOLVE_SQL_PLAN_BASELINE function shows which statistics are compared.

Plan was verified: Time used .06 seconds.
Plan passed performance criterion: 360.12 times better than baseline plan.
Plan was changed to an accepted plan.

                          Baseline Plan      Test Plan       Stats Ratio
                          -------------      ---------       -----------
Execution Status:              COMPLETE       COMPLETE
Rows Processed:                     100            100
Elapsed Time(ms):                 2.173           .033             65.85
CPU Time(ms):                     2.444              0
Buffer Gets:                        720              2               360
Physical Read Requests:               0              0
Physical Write Requests:              0              0
Physical Read Bytes:                  0              0
Physical Write Bytes:                 0              0
Executions:                           1              1

For queries a regular execution can be performed. But, what happens for INSERT/UPDATE/MERGE/DELETE statements? Do the SQL engine really execute them and modify data?

To answer these questions let’s have a look to an example based on a DELETE statement…

• Setup a table used for the test:

SQL> CREATE TABLE t (id, n, pad, CONSTRAINT t_pk PRIMARY KEY (id))
  2  AS
  3  SELECT rownum, mod(rownum,100), rpad('*',500,'*')
  4  FROM dual
  5  CONNECT BY level <= 10000;

SQL> execute dbms_stats.gather_table_stats(ownname => user, tabname => 't', method_opt => 'for all columns size 254')

• Create a SQL plan baseline:

SQL> ALTER SESSION SET optimizer_capture_sql_plan_baselines = TRUE;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> ALTER SESSION SET optimizer_capture_sql_plan_baselines = FALSE;

• Add a non-accepted execution plan to the SQL plan baseline:

SQL> CREATE INDEX i ON t (n);

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

• Display the content of the SQL plan baseline (notice that two execution plans are available):

SQL> SELECT * FROM table(dbms_xplan.display_sql_plan_baseline('SYS_SQL_373d78bbba048c24', NULL, 'basic'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

--------------------------------------------------------------------------------
SQL handle: SYS_SQL_373d78bbba048c24
SQL text: DELETE t WHERE n = 42
--------------------------------------------------------------------------------

--------------------------------------------------------------------------------
Plan name: SQL_PLAN_3fgbsrfx093143bad20a0         Plan id: 1001201824
Enabled: YES     Fixed: NO      Accepted: YES     Origin: AUTO-CAPTURE
--------------------------------------------------------------------------------

Plan hash value: 3335594643

-----------------------------------
| Id  | Operation          | Name |
-----------------------------------
|   0 | DELETE STATEMENT   |      |
|   1 |  DELETE            | T    |
|   2 |   TABLE ACCESS FULL| T    |
-----------------------------------

--------------------------------------------------------------------------------
Plan name: SQL_PLAN_3fgbsrfx093144198692b         Plan id: 1100507435
Enabled: YES     Fixed: NO      Accepted: NO      Origin: AUTO-CAPTURE
--------------------------------------------------------------------------------

Plan hash value: 1582806765

----------------------------------
| Id  | Operation         | Name |
----------------------------------
|   0 | DELETE STATEMENT  |      |
|   1 |  DELETE           | T    |
|   2 |   INDEX RANGE SCAN| I    |
----------------------------------

• Trace the evolution to find out what happens (notice that I deleted the output of the function because it is the one it is shown at the top of this post):

SQL> execute dbms_monitor.session_trace_enable(plan_stat=>'ALL_EXECUTIONS')

SQL> SELECT dbms_spm.evolve_sql_plan_baseline(
  2           sql_handle => 'SYS_SQL_373d78bbba048c24',
  3           plan_name  => '',
  4           time_limit => 10,
  5           verify     => 'yes',
  6           commit     => 'yes'
  7         )
  8  FROM dual;

SQL> execute dbms_monitor.session_trace_disable

SQL> SELECT value
  2  FROM v$diag_info
  3  WHERE name = 'Default Trace File';

VALUE
-------------------------------------------------------------------
/u00/app/oracle/diag/rdbms/dba112/DBA112/trace/DBA112_ora_17200.trc

Now that the trace file was generated, let’s have a look to its content. The relevant parts are two: the first one is related to the execution of the accepted execution plan, and the second one is related to the execution of the non-accepted one.

PARSING IN CURSOR #11 len=45 dep=1 uid=90 oct=7 lid=90 tim=1275524159625080 hv=4077337184 ad='325c9f10' sqlid='5fwyncmthffm0'
/* SQL Analyze(25,0) */ DELETE t WHERE n = 42
END OF STMT
PARSE #11:c=1000,e=652,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1001201824,tim=1275524159625078
EXEC #11:c=4999,e=5670,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159630752
EXEC #11:c=2000,e=1718,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159632613
EXEC #11:c=2000,e=1511,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159634156
EXEC #11:c=2000,e=1542,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159636144
EXEC #11:c=2000,e=1552,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159638151
EXEC #11:c=3998,e=4015,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159642613
EXEC #11:c=3000,e=2905,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159645549
EXEC #11:c=2000,e=1506,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159647151
EXEC #11:c=2000,e=1562,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159649160
EXEC #11:c=2999,e=2440,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159652037
CLOSE #11:c=0,e=3,dep=1,type=0,tim=1275524159652065

PARSING IN CURSOR #5 len=45 dep=1 uid=90 oct=7 lid=90 tim=1275524159657503 hv=4077337184 ad='325c9f10' sqlid='5fwyncmthffm0'
/* SQL Analyze(25,0) */ DELETE t WHERE n = 42
END OF STMT
PARSE #5:c=1000,e=859,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657499
EXEC #5:c=0,e=52,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657625
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657647
EXEC #5:c=0,e=31,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657972
EXEC #5:c=0,e=5,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
CLOSE #5:c=0,e=0,dep=1,type=0,tim=1275524159658071

In the previous output notice that:

• The PLH attribute of the EXEC lines shows that two execution plans are used.
• Each execution plan was executed 10 times (in practice the number varies according to the elapsed time; i.e. for longer executions a single run might be enough to determine whether an execution plan has to be accepted).
• Even though I set the PLAN_STAT parameter to ALL_EXECUTIONS (if you don’t know what the PLAN_STAT parameter is for, have a look to this post) the STAT lines (the execution plan) are not available in the trace file.

According to this information the SQL statement is executed. But, if you check the table after the evolution, the data is still there. And that, honestly, is not an option! In addition, no ROLLBACK is executed (no XCTEND lines are present in the trace file). So, it seems that the SQL statement is not executed.

What I really miss in the trace file are the execution plans associated to the executions to check what the different operations of the execution plan did. The only way I found to have them, it is to add the GATHER_PLAN_STATISTICS hint into the SQL statement itself (also setting the STATISTICS_LEVEL parameter and checking a view like V$SQL_PLAN_STATISTICS_ALL did not help). The content of the trace file, formatted by TVD$XTAT, is the following:

Optimizer Mode       ALL_ROWS
Hash Value           1001201824
Number of Executions 10

        Rows Operation
------------ ---------------------------------------------------------------------------------------
           0 DELETE  T (cr=720 pr=25 pw=0 time=0 us)
           0   TABLE ACCESS FULL T (cr=720 pr=25 pw=0 time=0 us cost=84 size=700 card=100)

Optimizer Mode       ALL_ROWS
Hash Value           1100507435
Number of Executions 10

        Rows Operation
------------ ---------------------------------------------------------------------------------------
           0 DELETE  T (cr=2 pr=0 pw=0 time=0 us)
           0   INDEX RANGE SCAN I (cr=2 pr=0 pw=0 time=0 us cost=1 size=700 card=100) (object id 93840)

Notice that while the number of logical reads (CR attribute) matches the report generated by the evolution, the number of rows returned by both steps of the execution plans is 0. And that, even though the index range scan should return 100 rows.

In summary, during an evolution the SQL engine processes the SQL statements in a special way. The data is accessed, but not modified. Hence, SQL statements are only partially executed. I do not regard this fact as a problem, though. In fact, the operations that modify data should always perform the same work independently on how the data to be modified is located (in the example given here, either with a full table scan or an index range scan).

The aim of this post is to describe a strange (buggy) situation that I observed recently. But before doing that, I shortly summarize what a parent cursor and a child cursor are as well as when they can be shared. By the way, I borrowed this description from the pages 20/21 of my book. Hence, if you are interested in more information about this topic refer to it…

The result of a parse operation is a parent cursor and a child cursor stored in the library cache.

The key information related to a parent cursor is the text of the SQL statement. Therefore, several SQL statements share the same parent cursor if their text is exactly the same (note that there is at least an exception to this, specifically when cursor sharing is used). In the following example, four SQL statements are executed. Two have the same text. Two others differ only because of lowercase and uppercase letters or blanks. Through the V$SQLAREA view, it is possible to confirm that three distinct parent cursors were created.

SQL> ALTER SYSTEM FLUSH SHARED_POOL;

SQL> SELECT * FROM t WHERE n = 1234;

SQL> select * from t where n = 1234;

SQL> SELECT * FROM t WHERE n=1234;

SQL> SELECT * FROM t WHERE n = 1234;

SQL> SELECT sql_id, sql_text, executions
  2  FROM v$sqlarea
  3  WHERE sql_text LIKE '%1234';

SQL_ID        SQL_TEXT                          EXECUTIONS
------------- --------------------------------- ----------
2254m1487jg50 select * from t where n = 1234             1
g9y3jtp6ru4cb SELECT * FROM t WHERE n = 1234             2
7n8p5s2udfdsn SELECT * FROM t WHERE n=1234               1

The key information related to a child cursor is the execution plan and the execution environment related to it. The execution environment is important because if it changes, the execution plan might change as well. As a result, several SQL statements are able to share the same child cursor only if they share the same parent cursor and their execution environments are compatible. To illustrate, the same SQL statement is executed with two different values of the initialization OPTIMIZER_MODE parameter. The result is that a single parent cursor and two child cursors are created.

SQL> ALTER SESSION SET optimizer_mode = all_rows;

SQL> SELECT count(*) FROM t;

COUNT(*)
----------
      1000

SQL> ALTER SESSION SET optimizer_mode = first_rows_10;

SQL> SELECT count(*) FROM t;

COUNT(*)
----------
      1000

SQL> SELECT sql_id, child_number, sql_text, optimizer_mode, plan_hash_value
  2  FROM v$sql
  3  WHERE sql_id = (SELECT prev_sql_id
  4  FROM v$session
  5  WHERE sid = sys_context('userenv','sid'));

SQL_ID        CHILD_NUMBER SQL_TEXT               OPTIMIZER_MODE PLAN_HASH_VALUE
------------- ------------ ---------------------- -------------- ---------------
5tjqf7sx5dzmj            0 SELECT count(*) FROM t ALL_ROWS            2966233522
5tjqf7sx5dzmj            1 SELECT count(*) FROM t FIRST_ROWS          2966233522

To know which mismatch led to several child cursors, you can query the V$SQL_SHARED_CURSOR view.

SQL> SELECT child_number, optimizer_mode_mismatch
  2  FROM v$sql_shared_cursor
  3  WHERE sql_id = '5tjqf7sx5dzmj';

CHILD_NUMBER OPTIMIZER_MODE_MISMATCH
------------ -----------------------
           0 N
           1 Y

So far, so good… Now, let’s see what’s strange…

The interesting thing to point out about the previous example is that while I set FIRST_ROWS_10 as optimizer mode, the V$SQL view displayed the value FIRST_ROWS. Mhmm… That’s strange… They are two different optimizer modes. They cannot be considered equivalent. What are the implications? It is just the view that provides the wrong information or the database engine is able to share the same child cursor even with two different values of the OPTIMIZER_MODE parameter? Let’s try it with FIRST_ROWS (i.e. without “_10”)…

 SQL> ALTER SESSION SET optimizer_mode = first_rows;

SQL> SELECT sql_id, child_number, sql_text, optimizer_mode, executions
  2  FROM v$sql
  3  WHERE sql_id = (SELECT prev_sql_id
  4                  FROM v$session
  5                  WHERE sid = sys_context('userenv','sid'));

SQL_ID        CHILD_NUMBER SQL_TEXT                          OPTIMIZER_MODE EXECUTIONS
------------- ------------ --------------------------------- -------------- ----------
5tjqf7sx5dzmj            0 SELECT count(*) FROM t            ALL_ROWS                1
5tjqf7sx5dzmj            1 SELECT count(*) FROM t            FIRST_ROWS              2

Oh, damn! Even though the OPTIMIZER MODE is set to a different value the same child cursor is used. Since in this particular situation the execution plans associated to both child cursors are the same (their hash value are equal), it’s not a real problem. But, in practice, it might be possible that two different optimizer modes lead to different execution plans. The following example illustrates this.

• Build a table for the test:

SQL> CREATE TABLE t AS
  2  SELECT rownum AS id, rpad('*',500,'*') AS pad
  3  FROM dual
  4  CONNECT BY level <= 1000;

SQL> CREATE UNIQUE INDEX i ON t (id);

SQL> execute dbms_stats.gather_table_stats(user, 'T')

• Show that different values of the OPTIMIZER_MODE parameter lead to different execution plans:

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1;

SQL> EXPLAIN PLAN FOR SELECT * FROM t WHERE id <= 500;

SQL> SELECT * FROM table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
Plan hash value: 242607798

------------------------------------------------------------------------------------
| Id  | Operation                   | Name | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |      |     3 |  1515 |     3   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T    |     3 |  1515 |     3   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | I    |       |       |     2   (0)| 00:00:01 |
------------------------------------------------------------------------------------

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

   2 - access("ID"<=500)

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1000;

SQL> EXPLAIN PLAN FOR SELECT * FROM t WHERE id <= 500;

SQL> SELECT * FROM table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   500 |   246K|    10   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T    |   500 |   246K|    10   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter("ID"<=500)

• Execute the test query with both values of the OPTIMIZER_MODE parameter:

SQL> ALTER SYSTEM FLUSH SHARED_POOL;

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1;

SQL> SELECT * FROM t WHERE id <= 500;

        ID PAD
---------- ----------
         1 **********
         2 **********
…
       499 **********
       500 **********

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1000;

SQL> SELECT * FROM t WHERE id <= 500;

        ID PAD
---------- ----------
         1 **********
         2 **********
…
       499 **********
       500 **********

• Show that a single execution plan was used for both executions:

SQL> SELECT * FROM table(dbms_xplan.display_cursor(NULL,NULL));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
SQL_ID  2vw03p929jzgz, child number 0
-------------------------------------
SELECT * FROM t WHERE id <= 500

Plan hash value: 242607798

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

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

   2 - access("ID"<=500)

SQL> SELECT sql_id, child_number, executions, optimizer_mode
  2  FROM v$sql
  3  WHERE sql_id = '2vw03p929jzgz';

SQL_ID        CHILD_NUMBER EXECUTIONS OPTIMIZER_MODE
------------- ------------ ---------- --------------
2vw03p929jzgz            0          2 FIRST_ROWS

Even though it is not very likely that this bug (yes, in my opinion something like this cannot be considered a restriction of the implementation…) has an impact on a production system, I really don’t understand why the developers didn’t implement it correctly. It should not be that difficult to manage a byte containing the information about the used optimizer mode! Note that this is not the only case where something like that happens with the first rows optimizer mode. For example, also in a trace file generated through SQL trace no difference is made between the old and the new first row optimizer. So, it seams that they really got it wrong.