Wednesday, May 11, 2011

Setting CUROSR_SHARING To FORCE causes large amount of child cursors for an insert statement

In a pre-production test, we found out that application did not use bind variables and there was no time to change code before the production rollout. So we suggested changing CURSOR_SHARING parameter from EXACT to FORCE in order to turn hard parse to soft parse. When testing this change for the two webservice functions , which mainly consists of two inserts, one update and bunch of select statements, the results are promising:

Summary of testing results from 15 min interval AWR reports from a 4-node 11.2.0.2 RAC database

2-node test (CURSOR_SHARING=EXACT)

dd1    DB Time:   23.04 (mins)  143 tx/s   Parses: 440.7 per sec  Hard parses: 315.2 per sec       
dd4    DB Time:   23.35 (mins)  140 tx/s   Parses: 414.4 per sec  Hard parses: 303.5 per sec               


2-node test (CURSOR_SHARING=FORCE)

dd1   DB Time:    16.68 (mins)  146 tx/s   Parses: 383.9 per sec  Hard parses: 2.6 per sec
dd4   DB Time:    16.01 (mins)  147 tx/s   Parses: 384.2 per sec  Hard parses: 2.6 per sec


-- dd1  Time Model Statistics (CURSOR_SHARING=FORCE) 
 
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                                666.6         66.6
DB CPU                                                  350.0         35.0
parse time elapsed                                       80.0          8.0
hard parse elapsed time                                  15.1          1.5
hard parse (sharing criteria) elapsed time                1.7           .2
PL/SQL execution elapsed time                             1.1           .1
hard parse (bind mismatch) elapsed time                   1.0           .1
PL/SQL compilation elapsed time                           0.8           .1
connection management call elapsed time                   0.4           .0
sequence load elapsed time                                0.4           .0
repeated bind elapsed time                                0.0           .0
DB time                                               1,000.9
background elapsed time                                 200.0
background cpu time                                     143.9
          -------------------------------------------------------------
 
-- dd1  Time Model Statistics (CURSOR_SHARING=EXACT) 

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
DB CPU                                                  728.2         52.7
sql execute elapsed time                                632.9         45.8
parse time elapsed                                      481.2         34.8
hard parse elapsed time                                 390.0         28.2
hard parse (sharing criteria) elapsed time                3.2           .2
hard parse (bind mismatch) elapsed time                   2.9           .2
PL/SQL execution elapsed time                             1.4           .1
PL/SQL compilation elapsed time                           1.2           .1
connection management call elapsed time                   0.5           .0
sequence load elapsed time                                0.5           .0
repeated bind elapsed time                                0.0           .0
failed parse elapsed time                                 0.0           .0
DB time                                               1,382.4
background elapsed time                                 261.8
background cpu time                                     115.5
          -------------------------------------------------------------
 

Bascially, we saw hard parse was greatly reduced. For the same level transaction rate, DB time was reduced from 46 min to 32 min after changing to FORCE. However, when another module was enabled and added to the two webserverice workload, things went wrong. We saw large amount of "cursor:mutex S" and "liberary cache lock" waits (>80% DB time). We identified an insert statement that has large amount of child cursors ( ~ 8000) caused the problem.

Below is a test case demonstrating large number of child cursors are created with CURSOR_SHARING=FORCE:

Test case 1

This test was carried out to repeat what we encountered in our pre-production test. Inserts into a table called MY_STB_LOG2 were performed with CUROSR_SHARING=FORCE, with 324 total number of inserts similar to the following:

insert into MY_STB_LOG2 values('0000043862420080','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-04 07:51:40.000',timestamp'2011-05-04 02:20:45.000',timestamp'2011-05-04 02:35:07.000','N','N','','','','P',SYSDATE);
insert into MY_STB_LOG2 values('0000048201268050','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:02:07.000',timestamp'2011-05-04 21:10:22.000','','N','N','','','','P',SYSDATE);


After run, checking v$sqlarea and v$sql, we got:


SQL> select sql_text,sql_id, executions from v$sqlarea where sql_text like 'insert into MY_STB_LOG2%';
 
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
SQL_ID        EXECUTIONS
------------- ----------
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
16yq35g1c433b         71
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",:"SYS_B_04",:"
SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
4yzz9r14n53fg         28
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",times
tamp:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
gpb19na8zd67s        210
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",timestamp:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
6ua1jndb5ud4x         15


SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;

SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;
 
SQL_ID          COUNT(*)
------------- ----------
gpb19na8zd67s        210
16yq35g1c433b         71
4yzz9r14n53fg         28
6ua1jndb5ud4x         15


It can be seen that we have 4 versions of insert statements after literals are replaced by system-generated bind varialbes. For each version, the execution times equal to the number of its child cursors. It indicates for every insert, Oracle actually does hard parse with extra cost to search child cursors.


When using Dion's script to query v$sql_shared_cursor, we can see the reason for unshared cursor is "HASH_MATCH_FAILED"




--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 0000000093C96F80
CHILD_NUMBER = 68
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 00000000AB5E4300
CHILD_NUMBER = 69
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 000000013C695090
CHILD_NUMBER = 70
HASH_MATCH_FAILED = Y
--------------------------------------------------



It should be noted that even application using the bind varialbe, this problem could occur. One possible solution is to use PL/SQL procedure to do the insert:


Test case 2

I create a procedure STB_INS (see appendix) to insert into a table called MY_STB_LOG3 ( same structure as LOG2), then I run 324 exec procedure such as:

exec STB_INS('0001097562293114','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:30:01.000',timestamp'2011-05-05 00:20:03.000',timestamp'2011-05-04 23:42:57.000','N','N','','','','P',SYSDATE);

exec STB_INS('0000027988805135','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:46:21.000',timestamp'2011-05-05 01:02:54.000',timestamp'2011-05-04 22:55:10.000','N','N','','','','P',SYSDATE);


After run, check v$sqlarea and v$sql

SQL>  select sql_id, sql_text, executions from v$sqlarea where sql_text like '%MY_STB_LOG3%';

SQL_ID
-------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
EXECUTIONS
----------
4fdv39rhjag5n
INSERT INTO MY_STB_LOG3 VALUES( :B13 ,:B12 ,:B11 ,:B10 ,:B9 ,:B8 ,:B7 ,:B6 ,:B5 ,:B4 ,:B3 ,:B2 ,:B1 )
       324



SQL> select count(*) from v$sql where sql_id='4fdv39rhjag5n';

  COUNT(*)
----------
         1



We see 324 executions shared same cursor.

Appendix

create or replace procedure stb_ins(
p_UNIT_ADDRESS             VARCHAR2
,p_BATCH_NUMBER            VARCHAR2
,p_RECEIVED_TIME           TIMESTAMP
,p_LAST_LOG_TIME           TIMESTAMP
,p_POWERON_TIME            TIMESTAMP
,p_POWEROFF_TIME           TIMESTAMP
,p_UNAVAILABLE_FLAG        VARCHAR2
,p_UNSUBSCRIBE_FLAG        VARCHAR2
,p_WORK_ID                 VARCHAR2
,p_STATUS_CODE             VARCHAR2
,p_STATUS_DESC             VARCHAR2
,p_PROC_STATUS             VARCHAR2
,p_CREATE_DATE             DATE
) 
is
begin
  insert into my_stb_log3 values(
               p_UNIT_ADDRESS           
                ,p_BATCH_NUMBER          
                ,p_RECEIVED_TIME         
                ,p_LAST_LOG_TIME         
                ,p_POWERON_TIME          
                ,p_POWEROFF_TIME         
                ,p_UNAVAILABLE_FLAG      
                ,p_UNSUBSCRIBE_FLAG      
                ,p_WORK_ID               
                ,p_STATUS_CODE           
                ,p_STATUS_DESC           
                ,p_PROC_STATUS            
                ,p_CREATE_DATE            
  );
  commit;
end;
/


Some related references about cursor sharing:

http://www.freelists.org/post/oracle-l/Multiple-SQL-version-count-with-cusror-sharingsimilar,5
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:599762300346943686
http://kerryosborne.oracle-guy.com/2009/06/oracle-11g-adaptive-cursor-sharing-acs/
http://download.oracle.com/docs/cd/E11882_01/server.112/e16638/optimops.htm#sthref874

No comments: