The issue had been related to a business-critical stored procedure that, for some reason, was performing almost 50% slower when run in 11gR2 compared to 9iR2. When I took a look at the procedure I've discovered that there were, strictly speaking, nothing that could regress. At least not in the commons sense when we're talking about upgrades. All the procedure was doing was a look up using a statement containing UNION ALL.
Below is the artificially created test case which demonstrates the issue.
9iR2 results:
select * from dual where :"SYS_B_0"=:"SYS_B_1" union all select * from dual where :"SYS_B_2"=:"SYS_B_3" call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 99999 3.88 4.41 0 0 0 0 Execute 99999 1.23 1.31 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 199998 5.11 5.73 0 0 0 0
11gR2 results:
select * from dual where :"SYS_B_0"=:"SYS_B_1" union all select * from dual where :"SYS_B_2"=:"SYS_B_3" call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 99999 6.14 7.21 0 0 0 0 Execute 99999 1.04 1.38 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 199998 7.19 8.59 0 0 0 0
As you can see from the above figures, 11gR2 spent significantly more time parsing. Given that both sessions had 100% session cursor cache hit (and yes, the procedure didn't make use of bind variables either) and were otherwise run on pretty much identical environments (apart from the Oracle version), such a difference in parse time is certainly unexpected.
It was another time to gear up for a reproducible test case. Perhaps I'm being lucky but it boiled down to a session_cache_cursors setting again. To better demonstrate the point I'm going to run the following anonymous PL/SQL block in my 11gR2 database:
SQL> begin 2 execute immediate 'alter session set cursor_sharing=force'; 3 for i in 1 .. 10 4 loop 5 execute immediate 'alter session set session_cached_cursors='||to_char(i*100); 6 for j in 1 .. 10000 7 loop 8 execute immediate 9 'select /* test_'||to_char(i*100)||' */ * from dual where '||to_char(j)||'='||to_char(j)|| 10 ' union all select * from dual where '||to_char(j)||'='||to_char(j); 11 end loop; 12 end loop; 13 end; 14 / PL/SQL procedure successfully completed
What it does is sets cursor_sharing=force and then executes the same statement with different settings for session_cached_cursors -- from 100 to 1000 (with 100 increment). What do you think the results would be?
SQL> select to_number(substr(sql_text, instr(sql_text, 'test')+5, 4)) cursor_cache, executions, cpu_time
2 from v$sql
3 where sql_text like '%test%'
4 and executions=10000
5 order by 1;
CURSOR_CACHE EXECUTIONS CPU_TIME
------------ ---------- ----------
100 10000 571916
200 10000 517928
300 10000 559908
400 10000 572909
500 10000 561912
600 10000 616915
700 10000 652899
800 10000 670886
900 10000 671892
1000 10000 702893
10 rows selectedSurprisingly enough, rising session_cached_cursors from 100 to 1000 increases the CPU time required to execute the statements from 571916 to 702893! You can also spot how the CPU time increases together with the session_cached_cursors setting.What happened is 9iR2 was running with session_cached_cursors=1000 and, apparently, it never had any negative effect... until the setting was transferred to 11gR2. It's somewhat hard to speculate what exactly is happening but based on my limited test cases it appears that you need (a) a union all in the statement, (b) run with cursor_sharing=force and (c) have literals in your query. Under these circumstances there appears to be that strange performance degradation observed in 11gR2. But I need to do more investigation on that one. For now all I can say is that, after setting session_cached_cursors=100, 11gR2 exhibited the same results as 9iR2.
***** UPDATE 07-Feb-2012 *****
It appears that only 11.2.0.1 and 11.2.0.2 are affected by this issue (see comments for more details).
***** UPDATE 07-Feb-2012 #2 *****
I've found the bug# for this one: "Bug 12345980 high parse time with cursor_sharing=force when session_cached_cursors set".
Posts
