Oracle Scratchpad

May 16, 2016

Cursor_Sharing problem

Filed under: 12c,Bugs,Oracle,Troubleshooting — Jonathan Lewis @ 12:49 pm GMT May 16,2016

Here’s a possible bug (though maybe “not a bug”) that came up over the weekend on the OTN database forum. An application generating lots of “literal string” SQL was tested with cursor_sharing set to force. This successfully forced the use of bind variable substitution, but a particular type of simple insert statement started generating very large numbers of child cursors – introducing a lot of mutex waits and library cache contention. Here’s a (substituted) statement that was offered as an example of the problem:


INSERT INTO schema.tableName (column1,columns2,..)
VALUES (:"SYS_B_0",:"SYS_B_1",:"SYS_B_2",:"SYS_B_3",:"SYS_B_4",:"SYS_B_5",:"SYS_B_6",timestamp:"SYS_B_7",SYSTIMESTAMP,:"SYS_B_8")

Note particularly the slightly odd looking detail: timestamp:”SYS_B_7″; this is how bind variable substitution looks if you’ve used the “compact” ANSI mechanism for handling datetime literals. We were told, in fact, that the tables had only number, varchar2, and date columns – so it looks a little suspicious when see timestamp values being inserted but the implied coercion wasn’t the source of the problem. Here’s all it takes to see the problem (tested only on 12.1.0.2):


rem
rem     Script:         ansi_datetime_bug.sql
rem     Author:         Jonathan Lewis
rem     Dated:          May 2016
rem

create table t1 (
        n1      number(8,0),
        v1      varchar2(10),
        d1      date,
        t1      timestamp
);

insert into t1 values(-1,'x',sysdate, systimestamp);

begin
        dbms_stats.gather_table_stats(
                ownname          => user,
                tabname          =>'T1',
                method_opt       => 'for all columns size 1'
        );
end;
/

set serveroutput off
alter session set cursor_sharing = force;

prompt  ============================
prompt  Testing DATE literals
prompt  Expect to see child number 2
prompt  ============================

insert into t1 values(1, 'A', date'2016-01-01', null);
insert into t1 values(1, 'A', date'2016-01-02', null);
insert into t1 values(1, 'A', date'2016-01-03', null);

select * from table(dbms_xplan.display_cursor(null,null,'-note -plan_hash'));

prompt  ============================
prompt  Testing TIMESTAMP literals
prompt  Expect to see child number 2
prompt  ============================

insert into t1 values(1, 'A', null, timestamp'2016-01-01 00:00:00');
insert into t1 values(1, 'A', null, timestamp'2016-01-02 00:00:00');
insert into t1 values(1, 'A', null, timestamp'2016-01-03 00:00:00');

select * from table(dbms_xplan.display_cursor(null,null,'-note -plan_hash'));

prompt  ===============================
prompt  Need privilege to see this view
prompt  Pre-coded for the sql_ids above
prompt  ===============================

break on sql_id skip 1

select
        sql_id, child_number, hash_match_failed
from
        v$sql_shared_cursor
where
        sql_id in ('58udhcm270bhn', 'gssz5cbnt7mgn')
order by
        sql_id, child_number
;

A couple of points – there are several more tests in the script demonstrating things that do NOT cause multiple child cursors to appear. I probably didn’t cover all the options that I could have covered but I hit a number of common cases to check that it wasn’t simply that cursor_sharing being severely broken in 12c. I’ve also allowed a side effect to demonstrate the presence of multiple child cursors rather than explcitly listing the child cursors. If the three statements (of each type) had produced shareable cursors then the child number reported by dbms_xplan.display_cursor() would have been zero in both cases. Here are the actual outputs:


SQL_ID  58udhcm270bhn, child number 2
-------------------------------------
insert into t1 values(:"SYS_B_0", :"SYS_B_1", date:"SYS_B_2", null)

-------------------------------------------------
| Id  | Operation                | Name | Cost  |
-------------------------------------------------
|   0 | INSERT STATEMENT         |      |     1 |
|   1 |  LOAD TABLE CONVENTIONAL | T1   |       |
-------------------------------------------------


SQL_ID  gssz5cbnt7mgn, child number 2
-------------------------------------
insert into t1 values(:"SYS_B_0", :"SYS_B_1", null, timestamp:"SYS_B_2")


-------------------------------------------------
| Id  | Operation                | Name | Cost  |
-------------------------------------------------
|   0 | INSERT STATEMENT         |      |     1 |
|   1 |  LOAD TABLE CONVENTIONAL | T1   |       |
-------------------------------------------------


And, having pre-coded the script with the SQL_IDs of the two guilty statements, here’s the output identifying the cause of the failure to share from v$sql_shared_cursor:


SQL_ID        CHILD_NUMBER H
------------- ------------ -
58udhcm270bhn            0 N
                         1 Y
                         2 Y

gssz5cbnt7mgn            0 N
                         1 Y
                         2 Y

There is a bug on MoS relating to timestamp columns and failure to share cursors – it doesn’t really look like the same problem but it could be related in some way: Bug 13407937 : HIGH VERSION COUNT FOR INSERT WITH CURSOR_SHARING=FORCE AND TIMESTAMP COLUMN. It’s described as “not a bug” :(

5 Comments »

  1. Hi Jonathan!
    I had a similar case (database 11.1.0.7 and 11.2.0.2):

    “WHERE TR.UPDATETIMESTAMP>=TIMESTAMP :”SYS_B_0″” was transformed in 10053 trace file to
    “WHERE SYS_EXTRACT_UTC(“TR”.”UPDATETIMESTAMP”)>=SYS_EXTRACT_UTC(TIMESTAMP’ 2012-02-15 16:08:00.679000000′)”

    but the syntax:
    “WHERE TR.UPDATETIMESTAMP >= to_timestamp(‘2012-02-15 14:08:00.679′,’YYYY-MM-DD HH24:MI:SS.FF’);”
    looked in the tracefile like this:
    “WHERE SYS_EXTRACT_UTC(“TR”.”UPDATETIMESTAMP”)>SYS_EXTRACT_UTC(TO_TIMESTAMP(:B1,:B2));”

    So it looks like at the low level, the CBO transforms query with ANSI syntax and bind variable – to regular literals.

    Best regards!
    Kamil.

    Comment by Kamil Stawiarski — May 16, 2016 @ 1:36 pm GMT May 16,2016 | Reply

    • Kamil, by the way, you’ll find that those SYS_EXTRACT_UTC functions are popping up all over because your table column has a data type of timestamp with time zone and you are comparing it to a timestamp. You should probably use to_timestamp_tz (or if you haven’t been scared off you can add the timezone into the timestamp literal form)

      I think the behaviour is probably to do with the fact that you can not use the datetime literals with bind variables;

      andy@orcl> var bindvar1 varchar2(50)
      andy@orcl> select * From as_test_dates where timestamp_col = timestamp:bindvar1;
      select * From as_test_dates where timestamp_col = timestamp:bindvar1
                                                                 *
      ERROR at line 1:
      ORA-00933: SQL command not properly ended
      

      This would suggest that all cursor_sharing=force was doing was masking the values in v$sql.sql_text. You can see the real values in an plan when they are used as a predicate (you don’t need to view the 10053 trace for this):

      PLAN_TABLE_OUTPUT
      --------------------------------------------------------------------------------------------
      SQL_ID  fg3gyvrksqgyr, child number 0
      -------------------------------------
      select * From as_test_dates where timestamp_col = timestamp:"SYS_B_0"
      
      Plan hash value: 2837681445
      
      -----------------------------------------------------------------------------------
      | Id  | Operation         | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
      -----------------------------------------------------------------------------------
      |   0 | SELECT STATEMENT  |               |       |       |     2 (100)|          |
      |*  1 |  TABLE ACCESS FULL| AS_TEST_DATES |     1 |    50 |     2   (0)| 00:00:01 |
      -----------------------------------------------------------------------------------
      
      Predicate Information (identified by operation id):
      ---------------------------------------------------
      
         1 - filter("TIMESTAMP_COL"=TIMESTAMP' 2012-02-15 16:08:00.679000000')
      
      Note
      -----
         - dynamic statistics used: dynamic sampling (level=2)
      

      I couldn’t find the same information for an insert-values statement but I would guess that the same thing is occurring.

      Comment by Andrew Sayer — May 18, 2016 @ 12:11 am GMT May 18,2016 | Reply

  2. Just last week I encountered a problem highlighting the dangers of using cursor_sharing=force.

    An OLTP application using an 11.2.0.3 Standard Edition database suddenly starting hitting ORA-04025 errors when under heavy load.

    Everything was pointing to a cursor problem of some sort but the application had not changed, and the database had not changed. The database was set to the default of cursor_sharing=exact.
    No sessions were ever quite reaching the maximum open cursors limit, and examination of trace files indicated library cache contention, and also we noticed very high CPU usage and library cache: mutex X waits.
    Using oradebug to produce a library cache dump showed us that certain cursors had very high ActiveLocks values, and to cut a long story short, the problem was eventually traced to the application’s Rails framework which was configured to use a value of cursor_sharing=force (the default in this version of Rails).

    Cursor_sharing was then changed to ‘exact’ in the Rails configuration, and hey presto, the problem disappeared.

    Oracle 11 documentation is very clear that cursor_sharing=force should be used only in exceptional circumstances, and only if all of the following conditions are met:

    • Statements in the shared pool differ only in the values of literals.
    • Response time is suboptimal because of a very high number of library cache misses.
    • Your existing code has a serious security and scalability bug—the absence of bind variables—and you need a temporary band-aid until the source code can be fixed.
    • You set this initialization parameter at the session level and not at the instance level.

    It goes on to say:

    Setting CURSOR_SHARING to FORCE has the following drawbacks:
    • It indicates that the application does not use user-defined bind variables, which means that it is open to SQL injection. Setting CURSOR_SHARING to FORCE does not fix SQL injection bugs or render the code any more secure. The database binds values only after any malicious SQL text has already been injected.
    • The database must perform extra work during the soft parse to find a similar statement in the shared pool.
    • The database removes every literal, which means that it can remove useful information. For example, the database strips out literal values in SUBSTR and TO_DATE functions. The use of system-generated bind variables where literals are more optimal can have a negative impact on execution plans.
    • There is an increase in the maximum lengths (as returned by DESCRIBE) of any selected expressions that contain literals in a SELECT statement. However, the actual length of the data returned does not change.
    • Star transformation is not supported.

    Unless you are running applications that do not use bind variables (and I believe firmly that all OLTP application should use them) cursor_sharing=force should be avoided.
    We just have to remember that the database is not the only place where you need to check this parameter.

    Comment by Peter Clark — June 4, 2016 @ 3:09 pm GMT Jun 4,2016 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.