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:
Post a Comment