Posts in category Query Optimizer

Related-Combine Operation „UNION ALL (RECURSIVE WITH)“

Jun10
2010 4 Comments Written by Christian Antognini

To make easier the interpretation of execution plans, in chapter 6 of TOP I defined three types of operations: standalone operations, unrelated-combine operations, and related-combine operations. For combine operations I also added a list of all operations of each type. Since in 11.2 a new related-combine operation is available, I decided to write this short post as addenda to the content of the book.

The new related-combine operation, named “UNION ALL (RECURSIVE WITH)”, is available to support the new recursive subquery factoring clause. Hence, it is used for hierarchical queries. The following query and its execution plan show an example:

SQL> WITH
  2    e (xlevel, empno, ename, job, mgr, hiredate, sal, comm, deptno)
  3    AS (
  4      SELECT 1, empno, ename, job, mgr, hiredate, sal, comm, deptno
  5      FROM emp
  6      WHERE mgr IS NULL
  7      UNION ALL
  8      SELECT mgr.xlevel+1, emp.empno, emp.ename, emp.job, emp.mgr, emp.hiredate, emp.sal, emp.comm, emp.deptno
  9      FROM emp, e mgr
 10      WHERE emp.mgr = mgr.empno
 11    )
 12  SELECT *
 13  FROM e;

-------------------------------------------------------------------------------
| Id  | Operation                                 | Name    | Starts | A-Rows |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                          |         |      1 |     14 |
|   1 |  VIEW                                     |         |      1 |     14 |
|   2 |   UNION ALL (RECURSIVE WITH) BREADTH FIRST|         |      1 |     14 |
|*  3 |    TABLE ACCESS FULL                      | EMP     |      1 |      1 |
|   4 |    NESTED LOOPS                           |         |      4 |     13 |
|   5 |     NESTED LOOPS                          |         |      4 |     13 |
|   6 |      RECURSIVE WITH PUMP                  |         |      4 |     14 |
|*  7 |      INDEX RANGE SCAN                     | EMP_MGR |     14 |     13 |
|   8 |     TABLE ACCESS BY INDEX ROWID           | EMP     |     13 |     13 |
-------------------------------------------------------------------------------

   3 - filter("MGR" IS NULL)
   7 - access("EMP"."MGR"="MGR"."EMPNO")
       filter("EMP"."MGR" IS NOT NULL)

Notice that there are actually two operations:

UNION ALL (RECURSIVE WITH) BREADTH FIRST
UNION ALL (RECURSIVE WITH) DEPTH FIRST

As their name suggest, the difference is due to the search clause that you can set to either BREADTH FIRST BY or DEPTH FIRST BY.

Reading an execution plan containing the “UNION ALL (RECURSIVE WITH)” operation is the same as reading one containing the “CONNECT BY WITH FILTERING” operation. As a matter of fact, the purpose of both operations is basically the same. Just notice that also the “PUMP” operation used in the execution plan differs. While in the former it is called “RECURSIVE WITH PUMP”, in the latter it is called “CONNECT BY PUMP”. But the difference, for the purpose of reading the execution plan, does not matter.

You find a full description on how to read such an execution plan in this post.

Posted in 11gR2, TOP

Evolution of a SQL Plan Baseline Based on a DELETE Statement

Jun07
2010 3 Comments Written by Christian Antognini

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).

Posted in 11gR1, 11gR2, SQL Trace

Optimizer Mode Mismatch Does Not Prevent Sharing of Child Cursor!?!?

Jun03
2010 4 Comments Written by Christian Antognini

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.

Posted in 10gR1, 10gR2, 11gR1, 11gR2, 9iR2, Bug, SQL Trace