Posts in category 9iR2

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, Bug, Query Optimizer, SQL Trace

Bind Variable Peeking: Bane or Boon?

Apr29
2010 1 Comment Written by Christian Antognini

Almost one year ago Iggy Fernandez asked me to write a short text for the Ask the Oracles column of the NoCOUG Journal. The topic was “Bind Variable Peeking: Bane or Boon?”. My text along with the ones of Wolfgang Breitling, Dan Tow and Jonathan Lewis were published in the August issue. For some (unknown) reasons I never published that text on this site. Today, I correct that oversight. The text can be downloaded from this page.

Posted in 10gR1, 10gR2, 11gR1, 11gR2, Query Optimizer

Tracing VPD Predicates

Feb28
2010 1 Comment Written by Christian Antognini

Even though a number of articles and blog posts have already been written on this topic (e.g. on Pete Finnigan’s site I found references dating back from 2003), from time to time I’m still asked “How to trace predicates generated by VPD?”. Hence, here’s yet another blog post about this topic…

Let’s setup the scene before explaining how you can do it:

The user named CHA owns the schema created with the script ?/sqlplus/demo/demobld.sql.
The data stored in the EMP table is the following:

SQL> SELECT * FROM emp;

     EMPNO ENAME      JOB              MGR HIREDATE         SAL       COMM     DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
      7369 SMITH      CLERK           7902 17-DEC-80        800                    20
      7499 ALLEN      SALESMAN        7698 20-FEB-81       1600        300         30
      7521 WARD       SALESMAN        7698 22-FEB-81       1250        500         30
      7566 JONES      MANAGER         7839 02-APR-81       2975                    20
      7654 MARTIN     SALESMAN        7698 28-SEP-81       1250       1400         30
      7698 BLAKE      MANAGER         7839 01-MAY-81       2850                    30
      7782 CLARK      MANAGER         7839 09-JUN-81       2450                    10
      7788 SCOTT      ANALYST         7566 09-DEC-82       3000                    20
      7839 KING       PRESIDENT            17-NOV-81       5000                    10
      7844 TURNER     SALESMAN        7698 08-SEP-81       1500          0         30
      7876 ADAMS      CLERK           7788 12-JAN-83       1100                    20
      7900 JAMES      CLERK           7698 03-DEC-81        950                    30
      7902 FORD       ANALYST         7566 03-DEC-81       3000                    20
      7934 MILLER     CLERK           7782 23-JAN-82       1300                    10

The data stored in the EMP table is protected by a VPD predicate created with the following commands:

SQL> CREATE OR REPLACE FUNCTION emp_restrict (p_schema IN VARCHAR2, p_table IN VARCHAR2) RETURN VARCHAR2 AS
  2  BEGIN
  3    RETURN '''' || sys_context('userenv','session_user') || ''' = ename';
  4  END emp_restrict;
  5  /

SQL> execute dbms_rls.add_policy('CHA','EMP','EMP_POLICY','CHA','EMP_RESTRICT');

Because of the VPD predicate, different users see different rows. Here an example:

SQL> connect scott

SQL> SELECT * FROM cha.emp;

     EMPNO ENAME      JOB              MGR HIREDATE         SAL       COMM     DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
      7788 SCOTT      ANALYST         7566 09-DEC-82       3000                    20

SQL> connect clark

SQL> SELECT * FROM cha.emp;

     EMPNO ENAME      JOB              MGR HIREDATE         SAL       COMM     DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
      7782 CLARK      MANAGER         7839 09-JUN-81       2450                    10

If the function used for the VPD policy is simple and does generate a predicate that can be correctly parsed, to view the predicate it is enough to give a look to the output of the dbms_xplan package. The following SQL statements illustrate this:

SQL> SELECT * FROM table(dbms_xplan.display_cursor(sql_id=>'dmc3z4t0u57y1', format=>'basic predicate'));

EXPLAINED SQL STATEMENT:
------------------------
SELECT * FROM cha.emp

Plan hash value: 3956160932

----------------------------------
| Id  | Operation         | Name |
----------------------------------
|   0 | SELECT STATEMENT  |      |
|*  1 |  TABLE ACCESS FULL| EMP  |
----------------------------------

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

   1 - filter("ENAME"='SCOTT')

Another possibility, if you have access to the V$VPD_POLICY view, is to execute a query like the following one:

SQL> SELECT predicate FROM v$vpd_policy WHERE sql_id = 'dmc3z4t0u57y1';

PREDICATE
----------------------
'SCOTT' = ename

However, in case you want to see the whole SQL statement or the predicate generated by the VPD policy leads to an ORA-28113 (policy predicate has error), there is no documented way I’m aware of to display the generated predicate. One of the undocumented ways to do it is to use the event 10730. Note that the event generates a trace file containing the information we are looking for in such situations. Here is an example:

Enable the event:

SQL> ALTER SESSION SET events '10730 trace name context forever, level 1';

Run the query that, for example, leads to an error (note that to generate the ORA-28113 I modified the EMP_RESTRICT function…):

SQL> SELECT * FROM cha.emp;
SELECT * FROM cha.emp
                  *
ERROR at line 1:
ORA-28113: policy predicate has error

Check the trace file generated by the database engine (note that the V$DIAG_INFO view is available as of 11g only):

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

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

SQL> host tail -10 /u00/app/oracle/diag/rdbms/dba112/DBA112/trace/DBA112_ora_31964.trc
-------------------------------------------------------------
Error information for ORA-28113:
Logon user     : SCOTT
Table/View     : CHA.EMP
Policy name    : EMP_POLICY
Policy function: CHA.EMP_RESTRICT
RLS view  :
SELECT  "EMPNO","ENAME","JOB","MGR","HIREDATE","SAL","COMM","DEPTNO" FROM "CHA"."EMP"   "EMP" WHERE ('SCOTT' = enamee)
ORA-00904: "ENAMEE": invalid identifier
-------------------------------------------------------------

As you can see, the trace file contains not only the whole SQL statement but also the reason for the ORA-28113 error.

Posted in 10gR1, 10gR2, 11gR1, 11gR2