Search

Top 60 Oracle Blogs

Recent comments

PL/SQL

Adaptive Cursor Sharing

This post was motivated by a recent discussion I had where I mentioned that Adaptive Cursor Sharing (ACS) does not work with embedded SQL in PL/SQL, but when looking for an existing post realized that I didn't find any good and freely available examples of that limitation of ACS.

Therefore I decided to put together this post that outlines what ACS is supposed to do, its inherent limitations and finally shed some light on the specific limitation that started its life with the description that "it does not work with embedded SQL in PL/SQL".

Adaptive Cursor Sharing (ACS) has been introduced in Oracle 11g to address the potential threat of cursor sharing and bind variables - yes, you have read correctly: The usage of bind variables can be a possible threat if different values of bind variables are executed using the same execution plan, but actually would require different execution plans to prevent poor performing executions.

So ACS allows Oracle to detect such problems and selectively "unshare" cursors, which means that Oracle creates one or more additional child cursors for different (ranges) of bind values.

However, there are a couple of limitations to this strategy. Let's have a look at a working example of ACS. Therefore I run the following script against database versions 11.1.0.7 and 11.2.0.2:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_1.sql
--
-- Purpose: Demonstrate a simple case of adaptive cursor sharing
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading off newpage none tab off serveroutput off

alter session set statistics_level = all;

alter system flush buffer_cache;

alter system flush shared_pool;

var x number

exec :x := 100000

-- pause

set timing on

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

column prev_sql_id new_value sql_id noprint
column sid new_value session_id noprint

select
prev_sql_id
, sid
from
v$session
where
sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

exec :x := 1

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

set heading on

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = '&sql_id';

and I get the following result from 11.2.0.2 (and 11.1.0.7):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75795

SQL>
SQL> set echo on linesize 200 heading off newpage none tab off serveroutput off
SQL>
SQL> alter session set statistics_level = all;

Session altered.

SQL>
SQL> alter system flush buffer_cache;

System altered.

SQL>
SQL> alter system flush shared_pool;

System altered.

SQL>
SQL> var x number
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

SQL>
SQL> -- pause
SQL>
SQL> set timing on
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.09
SQL>
SQL> column prev_sql_id new_value sql_id noprint
SQL> column sid new_value session_id noprint
SQL>
SQL> select
2 prev_sql_id
3 , sid
4 from
5 v$session
6 where
7 sid = sys_context('userenv', 'sid');

Elapsed: 00:00:00.15
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

-------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | 3 | | | |
| 2 | VIEW | | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
-------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:01.74
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.7361E+11

Elapsed: 00:00:17.12
SQL>
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:17.12 | 1460K| 35371 | 10532 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:17.12 | 1460K| 35371 | 10532 | | | | |
| 2 | VIEW | | 1 | 13 | 1457K|00:00:16.94 | 1460K| 35371 | 10532 | | | | |
| 3 | WINDOW SORT | | 1 | 13 | 1457K|00:00:16.66 | 1460K| 35371 | 10532 | 93M| 3313K| 37M (1)| 84992 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 13 | 1457K|00:00:12.01 | 1460K| 24839 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 13 | 1457K|00:00:01.53 | 3221 | 3220 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.17
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.7361E+11

Elapsed: 00:00:05.10
SQL>
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));
SQL_ID fmbq5ytmh0hng, child number 1
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 2719131525

----------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
----------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:05.10 | 21539 | 29966 | 8375 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:05.10 | 21539 | 29966 | 8375 | | | | |
| 2 | VIEW | | 1 | 1457K| 1457K|00:00:04.98 | 21539 | 29966 | 8375 | | | | |
| 3 | WINDOW SORT | | 1 | 1457K| 1457K|00:00:04.80 | 21539 | 29966 | 8375 | 74M| 2971K| 37M (1)| 67584 |
|* 4 | TABLE ACCESS FULL| T | 1 | 1457K| 1457K|00:00:01.38 | 21532 | 21528 | 0 | | | | |
----------------------------------------------------------------------------------------------------------------------------------------------

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

4 - filter("OBJECT_ID">:X)

24 rows selected.

Elapsed: 00:00:00.05
SQL>
SQL> set heading on
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = '&sql_id';
old 12: sql_id = '&sql_id'
new 12: sql_id = 'fmbq5ytmh0hng'
SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
fmbq5ytmh0hng 0 2 3 1460762 Y N
fmbq5ytmh0hng 1 1 0 21539 Y Y

Elapsed: 00:00:00.00
SQL>

So I intentionally use bind variables in a dangerous way here: The "object_id > :x" predicate is a potential threat - depending on the value of :x the usage of the index on OBJECT_ID can be a very good or a very bad idea.

From this example we therefore can tell a couple of things you should know about ACS:

1. ACS is not limited to the typical "skewed column data" / "histogram" case. We can see that I explicitly did not create any histograms (method_opt "for all columns size 1"), still ACS marked the cursor as "BIND_SENSITIVE" and eventually created a second child cursor with a more appropriate execution plan for the bind value, because it detected the "expression > :x" predicate.

2. However, and this one of the most important aspects, for ACS to detect the problem, it first has to go wrong at least once. As you can see from the example it was only the second execution using the "bad" bind value that created the child cursor. So depending on how "wrong" things can go - think of a more complex execution plan including multiple joins - it might already be "too late" for your application: If for example a query is not going to return in a reasonable amount of time your application might effectively be "broken" even if ACS might be able to "fix" the problem at the next execution...

3. Another important point to consider is that the ACS information is not stored persistently but only exists in the Shared Pool. This means, if the information is aged out of the Shared Pool for whatever reason, the same mistake has to be made again for ACS to detect the problem. So if your problematic cursors age out of the Shared Pool it will potentially go "wrong" again with the next execution before ACS can come for help.

From this you can see that - although ACS is a great feature - it is not a "Silver Bullet" for all possible cases. You still might need to help your database for those special cases where ACS is not able to support your application properly. How you can help your database? More on that later.

Now let's have a look at the point that ACS "does not work with embedded SQL in PL/SQL". Therefore I put together the following script that in principle does the same as the first script, but this time uses the most commonly used techniques in PL/SQL to execute SQL:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_2.sql
--
-- Purpose: Demonstrate adaptive cursor sharing is not working with PL/SQL when
-- optimizations are enabled, in particular holding cursors open
-- See bug 8357294
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading on tab off serveroutput off

set timing on

-- This is a workaround that disables also the cursor optimizations in PL/SQL
-- In particular the PL/SQL hold cursor open optimization
-- Therefore the cursor gets reparsed and ACS kicks in
alter session set session_cached_cursors = 0;
--
-- Does this make any difference? No
-- alter session set plsql_optimize_level = 0;

variable sql_id varchar2(255)

-- Static SQL
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
select
sum(row_num)
into
n_dummy
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > x
);
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

-- dynamic SQL with binds
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
execute immediate '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
)' into n_dummy using x;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

-- dynamic SQL with literals
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
execute immediate '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > ' || x || '
)' into n_dummy;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
b.sql_id
, b.child_number
, b.executions
, b.parse_calls
, b.buffer_gets
, b.is_bind_sensitive
, b.is_bind_aware
from
v$sql a, v$sql b
where
a.force_matching_signature = b.force_matching_signature
and a.sql_id = :sql_id;

set pagesize 0

select
c.*
from
v$sql a
, v$sql b
, table(dbms_xplan.display_cursor(b.sql_id)) c
where
a.force_matching_signature = b.force_matching_signature
and a.sql_id = :sql_id;

set pagesize 9999

-- dynamic SQL with binds + OPEN
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
c sys_refcursor;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
open c for '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
)' using x;
fetch c into n_dummy;
close c;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

So this script executes the same query as used in the first script ten times in a row, again deliberately using the same bind values in the same order: The first execution can benefit from the index, all following executions would better use a full table scan.

These are the different techniques used:

1. Static embedded SQL which are sometimes in PL/SQL are also called "implicit cursors". They should exhibit the same characteristics as explicitly declared cursors, which I haven't included in this script.

2. Dynamic SQL using EXECUTE IMMEDIATE and binds, so the cursor can still be shared

3. Dynamic SQL using EXECUTE IMMEDIATE and literals, which leads to different SQLs and therefore different parent cursors with potentially different executions plans since both will be parsed / optimized independently from each other

4. Dynamic SQL using OPEN / FETCH / CLOSE and binds, so the cursor again can be shared

And this is the result that I get from 11.2.0.2 (11.1.0.7 showed the same):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75819

SQL>
SQL> set echo on linesize 200 heading on tab off serveroutput off
SQL>
SQL> set timing on
SQL>
SQL> -- This is a workaround that disables also the cursor optimizations in PL/SQL
SQL> -- In particular the PL/SQL hold cursor open optimization
SQL> -- Therefore the cursor gets reparsed and ACS kicks in
SQL> -- alter session set session_cached_cursors = 0;
SQL> --
SQL> -- Does this make any difference? No
SQL> -- alter session set plsql_optimize_level = 0;

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> variable sql_id varchar2(255)
SQL>
SQL> -- Static SQL
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.03
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.63
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 select
12 sum(row_num)
13 into
14 n_dummy
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > x
24 );
25 if i = 1 then
26 select
27 prev_sql_id
28 into
29 :sql_id
30 from
31 v$session
32 where
33 sid = sys_context('userenv', 'sid');
34 end if;
35 end loop;
36 end;
37 /

PL/SQL procedure successfully completed.

Elapsed: 00:02:50.68
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
g89tq3q521rbg 0 10 1 13146414 Y N

Elapsed: 00:00:00.17
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID g89tq3q521rbg, child number 0
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 100000

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

5 - access("OBJECT_ID">:B1)

29 rows selected.

Elapsed: 00:00:01.86
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.09
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.84
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > :x
23 )' into n_dummy using x;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:03:17.26
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 10 1 13146434 Y N

Elapsed: 00:00:00.14
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

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

5 - access("OBJECT_ID">:X)

31 rows selected.

Elapsed: 00:00:01.35
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with literals
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.05
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.66
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > ' || x || '
23 )' into n_dummy;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:52.29
SQL>
SQL> select
2 b.sql_id
3 , b.child_number
4 , b.executions
5 , b.parse_calls
6 , b.buffer_gets
7 , b.is_bind_sensitive
8 , b.is_bind_aware
9 from
10 v$sql a, v$sql b
11 where
12 a.force_matching_signature = b.force_matching_signature
13 and a.sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
2tgumwrfx40bu 0 1 1 53 N N
03zrk5tr7zsn4 0 9 1 193851 N N

Elapsed: 00:00:00.10
SQL>
SQL> set pagesize 0
SQL>
SQL> select
2 c.*
3 from
4 v$sql a
5 , v$sql b
6 , table(dbms_xplan.display_cursor(b.sql_id)) c
7 where
8 a.force_matching_signature = b.force_matching_signature
9 and a.sql_id = :sql_id;
SQL_ID 2tgumwrfx40bu, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 100000 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | |
| 2 | VIEW | | 13 | 195 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">100000)

SQL_ID 03zrk5tr7zsn4, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | | |
| 2 | VIEW | | 1457K| 20M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

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

4 - filter("OBJECT_ID">1)

51 rows selected.

Elapsed: 00:00:01.24
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds + OPEN
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.04
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.66
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 c sys_refcursor;
5 begin
6 for i in 1..10 loop
7 if i = 1 then
8 x := 100000;
9 else
10 x := 1;
11 end if;
12 open c for '
13 select
14 sum(row_num)
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > :x
24 )' using x;
25 fetch c into n_dummy;
26 close c;
27 if i = 1 then
28 select
29 prev_sql_id
30 into
31 :sql_id
32 from
33 v$session
34 where
35 sid = sys_context('userenv', 'sid');
36 end if;
37 end loop;
38 end;
39 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:12.12
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

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

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

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

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.36
SQL>
SQL> set pagesize 9999
SQL>

So this script shows some interesting results:

1. It can be seen that ACS does not seem to work with several of the used variations: Both the static and the dynamic SQL using EXECUTE IMMEDIATE and binds do not create a second child cursor and re-use the same execution plan for all ten executions. Although the cursor has been marked as BIND_SENSITIVE, it has not been marked as BIND_AWARE.

Both execution variants also share the fact that there seems to be a PL/SQL optimization in place that allows to keep the cursors open - there is only a single PARSE call recorded in V$SQL for this SQL statement, although we loop through the same code ten times and therefore should in principle see as many parse as execution calls.

You would even see the same optimization in place when explicit cursors were used with explicit OPEN / FETCH / CLOSE calls: Albeit the explicit CLOSE you would still see only a single PARSE call for the statement - PL/SQL holds the cursor open for maximum performance and scalibility.

2. Another interesting side note is that the new feature "Cardinality Feedback" that has been introduced with Oracle 11.2 seems also to be not working in these examples, but this is definitely something for another post.

"Cardinality Feedback" allows Oracle to compare the cardinality estimates of the cost-based optimizer with the actual cardinalities at execution time and perform "instant tuning" by automatically adding OPT_ESTIMATE and other hints to the statement to correct the cardinality estimates and do a re-optimization of the "tuned" statement. Again this information only resides in the Shared Pool and will be potentially aged out like the ACS information.

3. The clear winner in terms of both elapsed and performed logical I/O is the third variant that creates two different cursors using literals. For both cursors the optimal execution plan has been found and nothing had to go "wrong" first to be fixed afterwards, therefore the total elapsed time and number of buffer gets is significantly lower than in the other cases. This gives us already a hint regarding the point "How can we help the database in such cases?"

Note also that although the number of buffer gets is significantly lower compared to the other cases, the elapsed time is not that much different, which is another example that buffer gets are not necessarily a good indicator for the overall work performed. In this particular case a lot of time is spent on writing and reading from the temporary tablespace for the WINDOW SORT operation, and since this operation has more or less to do the same work in all cases where the whole table needs to read in whatever efficient or inefficient way, the overall runtime does not differ as dramatically as the number of buffer gets. You could see this additional work in this example by checking the columns DISK_READS and DIRECT_WRITES from V$SQL and of course by checking the ASH / extended SQL trace profile.

4. The fourth variant using the dynamic SQL with OPEN obviously does not benefit from the PL/SQL optimization: V$SQL clearly shows that there have been as many PARSE calls as EXECUTE calls. Interestingly in this case ACS worked and created a second child cursor. This gives us already a hint what seems to prevent ACS from working.

The shown behaviour of ACS not working is officially documented in My Oracle Support, however not available in the Knowledge Base but only as bug number 8357294: ADAPTIVE CURSOR SHARING DOESN'T WORK FOR SQL FROM PL/SQL. It is interesting to note that the very detailed bug description does not mention a fix release or patch, but does mention that setting "session_cached_cursors" to 0 allows ACS again to work.

And indeed, when running the same script again with "session_cached_cursors" set to 0, I get this result:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75821

SQL>
SQL> set echo on linesize 200 heading on tab off serveroutput off
SQL>
SQL> set timing on
SQL>
SQL> -- This is a workaround that disables also the cursor optimizations in PL/SQL
SQL> -- In particular the PL/SQL hold cursor open optimization
SQL> -- Therefore the cursor gets reparsed and ACS kicks in
SQL> alter session set session_cached_cursors = 0;

Session altered.

Elapsed: 00:00:00.00
SQL> --
SQL> -- Does this make any difference? No
SQL> -- alter session set plsql_optimize_level = 0;
SQL>
SQL> variable sql_id varchar2(255)
SQL>
SQL> -- Static SQL
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.05
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.71
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 select
12 sum(row_num)
13 into
14 n_dummy
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > x
24 );
25 if i = 1 then
26 select
27 prev_sql_id
28 into
29 :sql_id
30 from
31 v$session
32 where
33 sid = sys_context('userenv', 'sid');
34 end if;
35 end loop;
36 end;
37 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:00.82
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
g89tq3q521rbg 0 2 3 1460742 Y N
g89tq3q521rbg 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID g89tq3q521rbg, child number 0
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 100000

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

5 - access("OBJECT_ID">:B1)

SQL_ID g89tq3q521rbg, child number 1
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 1

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

4 - filter("OBJECT_ID">:B1)

57 rows selected.

Elapsed: 00:00:01.50
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.07
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.70
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > :x
23 )' into n_dummy using x;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:12.41
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.13
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

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

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

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

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.10
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with literals
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.03
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.69
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > ' || x || '
23 )' into n_dummy;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:55.97
SQL>
SQL> select
2 b.sql_id
3 , b.child_number
4 , b.executions
5 , b.parse_calls
6 , b.buffer_gets
7 , b.is_bind_sensitive
8 , b.is_bind_aware
9 from
10 v$sql a, v$sql b
11 where
12 a.force_matching_signature = b.force_matching_signature
13 and a.sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
2tgumwrfx40bu 0 1 1 53 N N
03zrk5tr7zsn4 0 9 9 193851 N N

Elapsed: 00:00:00.11
SQL>
SQL> set pagesize 0
SQL>
SQL> select
2 c.*
3 from
4 v$sql a
5 , v$sql b
6 , table(dbms_xplan.display_cursor(b.sql_id)) c
7 where
8 a.force_matching_signature = b.force_matching_signature
9 and a.sql_id = :sql_id;
SQL_ID 2tgumwrfx40bu, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 100000 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | |
| 2 | VIEW | | 13 | 195 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">100000)

SQL_ID 03zrk5tr7zsn4, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | | |
| 2 | VIEW | | 1457K| 20M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

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

4 - filter("OBJECT_ID">1)

51 rows selected.

Elapsed: 00:00:01.17
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds + OPEN
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.04
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.73
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 c sys_refcursor;
5 begin
6 for i in 1..10 loop
7 if i = 1 then
8 x := 100000;
9 else
10 x := 1;
11 end if;
12 open c for '
13 select
14 sum(row_num)
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > :x
24 )' using x;
25 fetch c into n_dummy;
26 close c;
27 if i = 1 then
28 select
29 prev_sql_id
30 into
31 :sql_id
32 from
33 v$session
34 where
35 sid = sys_context('userenv', 'sid');
36 end if;
37 end loop;
38 end;
39 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:05.62
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

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

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

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

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.57
SQL>
SQL> set pagesize 9999
SQL>

Now in all cases where the cursor is potentially shared we can see that ACS eventually kicks in and creates a second child cursor. Notice however that this comes at a price: All cases show now that there are as many PARSE calls as executions.

So this seems to mean that disabling the session cursor cache actually disabled also the PL/SQL optimization that prevents the repeated PARSE calls by keeping the cursors open.

Remember that the session cursor cache is merely a means to make a soft PARSE call even _softer_ by avoiding the otherwise required access to the Shared Pool library cache resources because the cursor information has been cached in a private memory area of the process, but the session cursor cache does not avoid the PARSE call itself - this can only be done on application resp. client side, not on database side.

In order to understand if the session cursor cache or the "keep cursors open" optimization affects ACS we can run the following simple script:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_3.sql
--
-- Purpose: Check if the session cursor cache affects adaptive cursor sharing
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading off newpage none tab off serveroutput off

alter session set statistics_level = all;

-- alter session set session_cached_cursors = 0;

alter system flush buffer_cache;

alter system flush shared_pool;

var x number

exec :x := 100000

-- pause

set timing on

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

column prev_sql_id new_value sql_id noprint
column sid new_value session_id noprint

select
prev_sql_id
, sid
from
v$session
where
sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

column value new_value value_1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

set heading on

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = '&sql_id';

This script simply runs the same SQL that we already know sufficiently often to ensure that it gets cached in the session cursor cache by executing it at least three times. Then in one of the next executions the "bad" bind values is used to see if the caching in the session cursor cache somehow prevents ACS from kicking in. Here is the result, this time from 11.1.0.7 (but again I got the same from 11.2.0.2):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1385560 2 71521

SQL>
SQL> set echo on linesize 200 heading off newpage none tab off serveroutput off
SQL>
SQL> alter session set statistics_level = all;

Session altered.

SQL>
SQL> -- alter session set session_cached_cursors = 0;
SQL>
SQL> alter system flush buffer_cache;

System altered.

SQL>
SQL> alter system flush shared_pool;

System altered.

SQL>
SQL> var x number
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

SQL>
SQL> -- pause
SQL>
SQL> set timing on
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> column prev_sql_id new_value sql_id noprint
SQL> column sid new_value session_id noprint
SQL>
SQL> select
2 prev_sql_id
3 , sid
4 from
5 v$session
6 where
7 sid = sys_context('userenv', 'sid');

Elapsed: 00:00:00.06
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

-------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
-------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.46
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> column value new_value value_1
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5058

Elapsed: 00:00:00.01
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5058 as diff
session cursor cache hits 2

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5063

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5063 as diff
session cursor cache hits 2

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5069

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5069 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5080

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5080 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5090

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:17.12
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5090 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:17.10 | 1388K| 44110 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:17.10 | 1388K| 44110 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:16.03 | 1388K| 44110 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:16.03 | 1388K| 44110 | 10005 | 88M| 3227K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:09.70 | 1388K| 24154 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:01.39 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5100

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:12.94
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5100 as diff
session cursor cache hits 3

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | 88M| 3232K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:06.93 | 1388K| 24059 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:00.01 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5110

Elapsed: 00:00:00.01
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:06.02
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5110 as diff
session cursor cache hits 3

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | 88M| 3232K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:06.93 | 1388K| 24059 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:00.01 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

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

5 - access("OBJECT_ID">:X)

SQL_ID fmbq5ytmh0hng, child number 1
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 2719131525

----------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
----------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:05.99 | 21058 | 34648 | 7955 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:05.99 | 21058 | 34648 | 7955 | | | | |
| 2 | VIEW | | 1 | 1385K| 1385K|00:00:05.74 | 21058 | 34648 | 7955 | | | | |
| 3 | WINDOW SORT | | 1 | 1385K| 1385K|00:00:04.35 | 21058 | 34648 | 7955 | 69M| 2893K| 55M (1)| 64512 |
|* 4 | TABLE ACCESS FULL| T | 1 | 1385K| 1385K|00:00:00.01 | 21054 | 21049 | 0 | | | | |
----------------------------------------------------------------------------------------------------------------------------------------------

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

4 - filter("OBJECT_ID">:X)

49 rows selected.

Elapsed: 00:00:00.21
SQL>
SQL> set heading on
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = '&sql_id';
old 12: sql_id = '&sql_id'
new 12: sql_id = 'fmbq5ytmh0hng'
SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
fmbq5ytmh0hng 0 7 8 2777315 Y N
fmbq5ytmh0hng 1 1 0 21058 Y Y

Elapsed: 00:00:00.03
SQL>

So we can see that from the third execution on we seem to get a hit in the session cursor cache (increase from 2 to 3), but still ACS seems to work properly, although this time it had to go wrong twice before ACS created the second child cursor. We can also see that we still get as many PARSE calls as executions, so the session cursor cache does not avoid the parsing as outlined above.

All this seems to suggest that the ACS (and potentially the "Cardinality Feedback", too) code is only triggered by a PARSE call and not evaluated as part of an EXECUTE call.

But if this was the case, then by no means the problem would be limited to PL/SQL and its clever optimizations that try to hold cursors open to avoid repeated PARSE calls.

Actually one of the core principles that we are told to make an application as scalable as possible is to parse only once but execute many times. So let's try to simulate such a well behaving application with this simple Java code snippet that accesses the database via JDBC:

import java.sql.* ;

class JDBCQuery
{
public static void main( String args[] )
{
try
{
// Load the database driver
Class.forName( "oracle.jdbc.driver.OracleDriver" ) ;

// Get a connection to the database
Connection conn = DriverManager.getConnection("jdbc:oracle:thin:@host:port:sid",
"username", "pwd");

// Print all warnings
for( SQLWarning warn = conn.getWarnings(); warn != null; warn = warn.getNextWarning() )
{
System.out.println( "SQL Warning:" ) ;
System.out.println( "State : " + warn.getSQLState() ) ;
System.out.println( "Message: " + warn.getMessage() ) ;
System.out.println( "Error : " + warn.getErrorCode() ) ;
}

// Reset the buffer cache and shared pool
Statement ddl = conn.createStatement();
ddl.executeUpdate("alter system flush shared_pool");
ddl.executeUpdate("alter system flush buffer_cache");
ddl.close();

// Prepare the statement
String query =
"select\n" +
" sum(row_num)\n" +
"from\n" +
" (\n" +
" select\n" +
" row_number() over (partition by object_type order by object_name) as row_num\n" +
" , t.*\n" +
" from\n" +
" t\n" +
" where\n" +
" object_id > ?\n" +
" )";

PreparedStatement stmt = conn.prepareStatement(query);

System.out.println(query);

Integer i;
Integer id;

for (i = 1; i <= 10; i++)
{
if (i == 1)
{
id = 100000;
}
else
{
id = 1;
}

System.out.println( "Iteration: " + i.toString() ) ;

stmt.setInt(1, id);

long startTime = System.currentTimeMillis();

// Execute the query
ResultSet rs = stmt.executeQuery();

// Loop through the result set
while( rs.next() )
System.out.println( rs.getLong(1)) ;

// Close the result set
rs.close() ;

long endTime = System.currentTimeMillis();

float seconds = (endTime - startTime) / 1000F;

// Elapsed time
System.out.println(Float.toString(seconds) + " seconds.");
}

stmt.close() ;
conn.close() ;
}
catch( SQLException se )
{
System.out.println( "SQL Exception:" ) ;

// Loop through the SQL Exceptions
while( se != null )
{
System.out.println( "State : " + se.getSQLState() ) ;
System.out.println( "Message: " + se.getMessage() ) ;
System.out.println( "Error : " + se.getErrorCode() ) ;

se = se.getNextException() ;
}
}
catch( Exception e )
{
System.out.println( e ) ;
}
}
}

/*
Check the Shared Pool by this query:

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, disk_reads
, direct_writes
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = 'cq3a8ukkws0su';

*/

This (by no means elegant or clever) piece of Java code again tries to do the same as our previous examples: It executes the known query ten times but behaves well since it parses only once and executes ten times using the two different bind values as already done before.

I only tested this with the JDBC thin driver that comes with Oracle 11.2.0.2 but not with the thick driver. However, since I assume that 95%+ of all Java applications out there actually use the thin driver this probably covers the most relevant case.

The results correspond to those of the PL/SQL examples with the "keep cursors open" optimization enabled: Neither ACS nor "Cardinality Feedback" kick in, and the SQL is executed every time using the same execution plan. The SQL is only parsed once, so the problem is not really limited to PL/SQL, but to every application that tries to avoid parse calls.

Summary

ACS is a great feature, but you need to be aware of its limitations, the most important being:

- Things have to go wrong first before ACS will be able to provide a fix. Depending on how "wrong" things can go, this might mean that ACS is actually not able to provide an efficient fix for certain cases
- The ACS information can be aged out of the Shared Pool which might lead to repeated "things have to go wrong" cases
- ACS is only triggered by explicit PARSE calls, it is not activated if the application parses once and executes many times

If you have a case where you need to help (or "co-operate" as Jonathan Lewis calls it in his brilliant presentation of the same name) your database, the simplest strategy is to use literals instead of bind variables. If you can't do this due to the issues introduced by this strategy (excessive hard parses, increased CPU and Shared Pool usage, library cache contention etc.) a more complex strategy - if applicable - is to "know your data" and generate a minimum amount of cursors that try to cover the cases where a different execution plan is desired.

This means something like this in pseudo code:

- If "known value A that requires a special treatment" then
-- execute SQL with dummy hint "A" or additional non-modifying predicate "A" = "A" to make the SQL unique
- If "known value B that requires a special treatment" then
-- execute SQL with dummy hint "B" or additional non-modifying predicate "B" = "B" to make the SQL unique
- Else "in all other cases"
-- execute SQL as is

Notice that using comments to make the SQL unique might not lead to the expected result since there are cases/environments where comments are stripped prior to execution.

Update: From a comment by Sokrates below that for some reason didn't make to the comments section but also doesn't show up in the "Spam" comments of the blog control panel I see that above description "dummy hint" might need a bit more explanation.

By "dummy hint" I mean to say that you should use hint syntax rather than normal comment syntax to make the SQL unique, because the normal comment might get filtered out whereas the comment using hint syntax is supposed to be kept. By "dummy hint" I mean any invalid hint comment in order to prevent any influence on the optimizer, for example /*+ CASE_A */ rather than /* CASE_A */

Advert: PL/SQL Masterclass Updates…

This month I’ll be doing some PL/SQL Masterclasses for Oracle University. The following dates have been confirmed:

  • Singapore (14-15)
  • Syndey (18-19)
  • Melbourne (21-22)

For more details contact Oracle University here.

Originally there was an extra session in Hong Kong, but this has now been cancelled.

In November the following dates are scheduled:

  • Bulgaria (22-23)
  • Serbia (25-26)

Cheers

Tim…

Advert: Asia Pacific PL/SQL Masterclasses…

It’s a little over a month before I start a run of four PL/SQL Masterclasses in the Asia Pacific region.

  • Singapore (14-15 October)
  • Syndey (18-19 October)
  • Melbourne (21-22 October)
  • Hong Kong (25-26 October)

If you are interested, contact Oracle and get booked on. The details are here: APAC Seminars.

Cheers

Tim…

DBMS_PARALLEL_EXECUTE

Here is a recent thread from OTN forums. The question raised is WTF? whether a hint in the examples section of DBMS_PARALLEL_EXECUTE documentation have to be used or not and why it is there. What do you think about it? Have a look in the documentation and mark your choice in a poll: PS. In [...]

Advanced Oracle Troubleshooting Session - PGA/UGA memory fragmentation

A troubleshooting session at one of my clients started with the following description of the problem:

In some specific database environments sometimes (but not always) a particular batch process takes significantly longer than expected - which in that case meant hours instead of a few minutes.

It could also be observed that particular SQL statements showed up as most prominent in that case when monitoring the process.

So the first thing was to be able to reproduce the issue at will which was not the case so far.

It was quite quickly possible to narrow the problem down to a single call to a complex PL/SQL stored procedure (that was part of a package and called a lot of other stored procedures / packages) that dealt with handling of LOBs representing XML data.

It turned out that by simply calling this stored procedure multiple times in a loop the issue could be reproduced at will and also in different database environments as initially reported.

The rather unique aspect of that stored procedure was that it got executed in an "exclusive" mode which means that it was run on a quite large IBM pSeries server (AIX 5.3, 11.1.0.7, 240 GB RAM, numerous P6 multi-cores, expensive storage) with no other business processes active at the same time. It was mostly a serial execution and when it was monitored, it spent most of its time in two SQL statements that were very simple and straightforward. It actually were static SQLs embedded in PL/SQL that queried a single, very small table using a unique index access plus a table access by ROWID. So we had two SQL statements that under normal circumstances at most could generate two logical I/Os per execution, since the index/table queried was so small and therefore was completely held in the buffer cache.

When monitoring the executions of these SQLs while running the above mentioned loop it became obvious that due to the design of the logic these SQL statements very called numerous times, actually thousands of times (depending on the content of the XML LOB), per procedure call.

It also became obvious that, because it was static SQL, the PL/SQL cursor cache (and the database block cache both) did a very good job - meaning that the SQLs were only parsed once and from then on only executed, and generated only logical I/O and no physical I/O.

Furthermore due to the logic implemented most of the time these SQLs actually didn't find the value looked up in the small table which meant that on average each of the execution required only a single logical I/O - the index unique scan that required only a single logical I/O and no further activity as the value could not be found in the index.

When checking the SQL execution statistics in different environments (Linux instead of AIX) it also became obvious that the same SQL statements were executed a similar number of times, but these environments didn't experience the same long runtime of the batch job, so the sheer number of SQL executions looked odd but didn't seem to be the root cause of the problem.

So we ended up with the following initial summary:

- We identified a stored procedure that deals with LOBs representing XML as culprit
- Due to the logic most of the time was spent in two static SQLs that got executed thousands of times per execution of the stored procedure
- However these SQLs used the "optimal" execution plan and actually generated only a single logical I/O per execution
- Furthermore due to the "exclusive" manner of the batch job no contention with other processes was possible
- So there are no usual suspects like "inefficient execution plans", "contention for resources", "serialization" etc.
- Therefore the usual performance monitoring methods like wait interface, extended SQL trace, active session history, session statistics / system statistics, ASH / AWR / ADDM reports didn't reveal any obvious culprit
- Executing the SQL statements identified in a separate process showed that they took on average 10 microseconds (!) per execution - which is quite fast and raised the question how it was possible that these statements showed up as the problematic ones - executed in a simple loop ten thousands of executions were possible within a single second.

So we were at a point where we basically had the classic "The Wait Interface Is Useless (Sometimes)" situation. All we could see is that most of the time was spent executing these SQLs and all we saw was that this time was spent on the single CPU executing these statements.

But wait, there was an interesting point showing up when monitoring the session statistics delta (e.g. using Tanel Poder's "snapper" utility): The process required more and more PGA/UGA memory while executing.

So it was time for advanced troubleshooting techniques - and for instance OakTable fellow Tanel Poder has done a lot of research in this area and provides numerous helpful tools.

Further checks revealed a few anomalies that allowed us to get an idea in which direction to investigate further:

- The PGA/UGA consumption of the process was increasing with every iteration of the loop executing the PL/SQL stored procedure. So there was a memory problem somewhere hidden. A good idea therefore seemed to be to take a PGA/UGA heapdump of the process to see what kind of memory chunks could be identified.

Caution: Taking heapdumps may crash your system or process, therefore be very cautious when doing so in a production-like environment. Taking PGA heapdumps usually only affects a single process and is therefore not that critical (unless it was a background process for instance...).

This is how you can take a heapdump using EVENTS:

ALTER SESSION SET EVENTS 'immediate trace name heapdump level ';

This is how you can request a heapdump using ORADEBUG:
AS SYSDBA after identifying the process using SETOSPID, SETORAPID OR SETMYPID:

ORADEBUG DUMP HEAPDUMP

See also Julian Dyke's website for an overview of the available heapdump levels.

In this case a level 4 + 1 = level 5 heapdump (PGA + UGA summary) seemed to to sufficient (although the current/user callheap might also be of interest which is level 8 + 16 + 4 + 1 = 29).

In our chapter 8 of the Expert Oracle Practices from the OakTable book Charles and I also describe the most important heapdump variants and the other performance monitoring methods applied here.

The trace file written can then be analyzed for example using Tanel's heapdump_analyzer shell script to get an initial overview - in this case since it was quite a huge trace file I simply used a slightly modified version of the awk program used by heapdump_analyzer to generate an input file for the Oracle external table feature to run more sophisticated reports on the file.

This is the Unix command that can be used to transform the raw trace into a suitable input for an Oracle external table:

cat $TRACE_FILE | awk '
/^HEAP DUMP heap name=/ { split($0,ht,"\""); HTYPE=ht[2]; doPrintOut = 1; }
/Chunk/{ if ( doPrintOut == 1 ) {
split($0,sf,"\"");
printf "%10d , %16s, %16s, %16s\n", $4, HTYPE, $5, sf[2];
}
}
/Total heap size/ {
doPrintOut=0;
}
' > $EXT_TAB_DIR/heapdump.txt

This is how this external table definition could look like:

create table heapdump
(
chunk_size integer
, heap_type varchar2(16)
, chunk_type varchar2(16)
, alloc_reason varchar2(16)
)
organization external
(
type oracle_loader
default directory ext_tab_dir
access parameters
(
records delimited by newline
fields terminated by ','
lrtrim
)
location ('heapdump.txt')
);

- The process "leaked" temporary lobs - in V$TEMPORARY_LOBS an ever increasing number of LOBs could be observed, however the increase was slow (one per execution of the stored procedure) and the space consumption in the temporary tablespace was low

- When calculating the average execution time of the two SQL statements getting executed many times it became obvious that these actually started as quickly observed in the separate execution but continuously slowed down - they became slower and slower over time

- After a couple of minutes these statements that initially took a few microseconds took already milliseconds (!) to execute - it was no wonder that the batch job took hours, since it still required to execute these statements numerous times, but now each execution took more than thousand times longer than in the beginning

- Looking closer it became obvious that every SQL statement that got executed was affected by that slowdown, but since many of these statements took several milliseconds anyway and were executed not that many times, an "overhead" of a few milliseconds didn't really make a significant difference. It were those statements that were executed that often that incurred the biggest penalty

- Eventually when the loop completed that executed the PL/SQL stored procedure, it became obvious that basically everything that was done within that session was affected, for example a simple SELECT * FROM DUAL or a null PL/SQL block like BEGIN NULL; END; took something like 30 centiseconds (0.3 secs!) to complete - doing the same in a fresh session (while the other session was still open) completed instantly (less than the 0.01 seconds measured by the SQL*Plus timing facility) - it was something that was specific to the session and not an instance-wide effect.

So there was something that obviously took more and more CPU time that added an overhead to basically "every" operation, no matter what was performed.

Time to go one level deeper and take traces on the O/S level to find out where a process was spending most of its time. Unfortunately this was AIX 5.3, so the range of available tools to perform such a measurement was quite limited. There is no DTrace on AIX, and the new probevue tool is only available from AIX 6 on. So we were left with Oracle's built-in oradebug short_stack and AIX's procstack tool to take samples of the call stack of the foreground process.

But Tanel is there again for a rescue - using his "OStackProf" tool set we were able to take samples of the call stack, only to find out that the process spent most of its time in memory management calls, and that was only an assumption since no-one could tell us what these sampled function names exactly meant. According to the MOS document 175982.1 these were related to memory management of ADTs (Oracle objects).

This is what such a stack trace sample looked like:

Below is the stack prefix common to all samples:
------------------------------------------------------------------------
Frame->function()
------------------------------------------------------------------------
# 36 ->main()
# 35 ->opimai_real()b0
# 34 ->sou2o()
# 33 ->opidrv()
# 32 ->opiodr()b98
# 31 ->opiino()f0
# 30 ->opitsk()
# 29 ->ttcpip()c
# 28 ->opiodr()b98
# 27 ->kpoal8()c
# 26 ->opiexe()
# 25 ->kkxexe()c
# 24 ->peicnt()
# 23 ->plsql_run()
# 22 ->pfrrun()
# 21 ->pfrrun_no_tool()c
# 20 ->pfrinstr_EXECC()c
# 19 ->pevm_EXECC()e4
# 18 ->psdnal()c
# 17 ->psddr0()
# 16 ->rpidrv()
# ...(see call profile below)
#
# -#--------------------------------------------------------------------
# - Num.Samples -> in call stack()
# ----------------------------------------------------------------------
76 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()b98->opipls()->opiexe()e4->auddft()b8->audbeg()->ktcxbr0()a0->kocbeg()->koctxbg()->kohalc()->kohalmc()->kghfru()c->44c0->->
20 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()b98->opipls()->opiexe()->44c0->->
1 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()b98->opipls()->opiexe()b8c->kksfbc()ec->ktcsna()c->ktucloGetGlobalMinScn()->44c0->->
1 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()b98->opipls()->opiexe()->ksuvrl()c->44c0->->
1 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()b98->opipls()->opiexe()->44c0->->
1 ->rpiswu2()c0->rpidru()->skgmstack()c4->rpidrus()c8->opiodr()->ksuprc()c->44c0->->

The "auddft"/"audbeg" function names might indicate something related to auditing, but the database didn't have any auditing enabled, apart from the "audit_trail = DB" setting. Alex Fatkulin recently reported an issue with auditing enabled slowing down 11.2.0.1 and indeed when setting "audit_trail = NONE" in 11.1.07 or 11.2.0.1 the slow-down experienced was less which indicates that there are actually some code paths related to auditing involved, however it didn't solve the issue - there was still a significant slow-down observed.

The crucial hint came from the analysis of the PGA/UGA heapdump:
The PGA/UGA heapdump showed hundred of thousands very small chunks that seem to relate to XML handling ("qmxdpls_subhea") - hence the obvious assumption was that something related to XML object memory management was probably going wrong.

Therefore we focused on the code parts that performed the XML processing - and very quickly a crucial bug was identified: The DBMS_XMLDOM.FREEDOCUMENT call was missing from the code.

Apparently this bug was in the code right from the beginning but the application was initially developed on 10.2 which interestingly does not show the same slow down. It shows the same symptoms however, like increasing PGA/UGA memory consumption and leaked temporary lobs, but it doesn't experience the same slow-down. Now that the database has been upgraded to 11.1.0.7 some time ago obviously the slow-down problems started to surface.

So by simply adding or removing the freedocument call from the code, the issue could be reproduced / fixed.

This enabled us to come up with a generic testcase that allows to reproduce the issue at will in most environments running 11.1.0.7 or later.

Note that it looks like that the effect seems to depend on the port of Oracle - Oracle 11.1.0.7 on Linux x64 showed a bit different behaviour - only some SQL statements were affected by the slow-down, but not every statement as it seems to be the case with the AIX port.

drop table t_testloop;

purge table t_testloop;

create table t_testloop (
id integer not null
, vc varchar2(255)
, constraint t_testloop_pk primary key (id)
)
;

insert into
t_testloop
(
id
, vc
)
select
level as id
, rpad('x', 100, 'x') as vc
from
dual
connect by
level <= 100;

commit;

exec dbms_stats.gather_table_stats(null, 'T_TESTLOOP')

-- This is supposed to be a INDEX UNIQUE SCAN + TABLE ACCESS BY ROWID
explain plan for
select
id
, vc
from
t_testloop
where
id = to_number(:x);

set linesize 160
set pagesize 999

select * from table(dbms_xplan.display);

set timing on echo on serveroutput on

-- This is the normal (reference) execution time for running
-- the simple statement a thousand times
declare
procedure check_key
as
x integer;
n_id integer;
s_vc varchar2(255);
begin
x := 42 * 3;
select
id
, vc
into
n_id
, s_vc
from
t_testloop
where
id = x;
exception
when NO_DATA_FOUND then
null;
end;
begin
for i in 1..1000 loop
check_key;
end loop;
end;
/

-- "Deterministic" randomness :-))
exec dbms_random.seed(0)

declare
start_time number;
end_time number;

-- Generate some CLOB containing XML
-- Note that it looks like the CLOB needs
-- to be different for every iteration
-- otherwise the issue couldn't be reproduced
function return_clob return clob
as
the_lob clob;
s_name varchar2(20);
n_sal integer;
s_job varchar2(20);
begin
the_lob := '
';
for i in 1..20 loop
s_name := dbms_random.string('U', trunc(dbms_random.value(1, 21)));
n_sal := trunc(dbms_random.value(1, 1001));
s_job := dbms_random.string('U', trunc(dbms_random.value(1, 21)));
the_lob := the_lob || '
' || to_char(i, 'TM') || '
' || s_name || '
' || to_char(n_sal, 'TM') || '
' || s_job || '

';
end loop;
the_lob := the_lob || '
';

return the_lob;
end return_clob;

-- Some usage of the PL/SQL XML DOM API
-- Some dummy processing of the attributes of the given node
procedure process_attributes
(
in_node dbms_xmldom.DOMNode
)
is
len number;
n dbms_xmldom.DOMNode;
nnm dbms_xmldom.DOMNamedNodeMap;
key varchar2(1000);
val varchar2(32767);
BEGIN
nnm := dbms_xmldom.getAttributes(in_node);

if (dbms_xmldom.isNull(nnm) = FALSE) then
len := dbms_xmldom.getLength(nnm);

-- loop through attributes
for i in 0..len-1 loop
n := dbms_xmldom.item(nnm, i);
key := dbms_xmldom.getNodeName(n);
val := dbms_xmldom.getNodeValue(n);
end loop;
end if;

end process_attributes;

-- Some usage of the PL/SQL XML DOM API
-- Recursively walk the nodes of the DOM
-- and call the attribute processing per node
procedure walk_node
(
in_node dbms_xmldom.DOMNode
)
is
nl dbms_xmldom.DOMNodeList;
len number;
n dbms_xmldom.DOMNode;
node_name varchar2(100);
begin
-- loop through elements
node_name:=dbms_xmldom.getNodeName(in_node);

process_attributes(in_node);

nl := dbms_xmldom.getChildNodes(in_node);
len := dbms_xmldom.getLength(nl);
for i in 0..len-1 loop
n := dbms_xmldom.item(nl, i);
node_name := dbms_xmldom.getNodeName(n);
walk_node(n);
end loop;
end walk_node;

-- The main procedure
procedure process_xml_clob
as
the_lob clob;
var XMLType;
doc dbms_xmldom.DOMDocument;
root dbms_xmldom.DOMNode;
root_tag varchar2(100);
begin
-- Get the CLOB with the XML
the_lob := return_clob;

-- Instantiate an XMLTYPE
var := xmltype(the_lob);

-- Generate a new DOM document from the XMLType
-- This seems to allocate a temporary LOB under the covers
doc := dbms_xmldom.newDOMDocument(var);

-- Some rudimentary XML DOM processing
root := dbms_xmldom.makeNode(dbms_xmldom.getDocumentElement(doc));

root_tag := dbms_xmldom.getNodeName(root);

-- If you want to burn more CPU to exaggerate the effect
-- uncomment this
-- walk_node(root);

-- This omission here causes a significant PGA/UGA memory leak
-- and causes version 11.1 and 11.2 to slow down everything
-- in this session
-- Version 10.2 suffers from the same symptoms but doesn't slow down
--DBMS_XMLDOM.freeDocument(doc);
end;
begin
-- Run this a thousand times and measure / output the runtime per execution
for i in 1..1000 loop
start_time := dbms_utility.get_time;
process_xml_clob;
end_time := dbms_utility.get_time;
dbms_output.put_line('Run ' || to_char(i, 'TM') || ': Time (in seconds)= ' || ((end_time - start_time)/100));
end loop;
end;
/

-- Do the simple statement again a thousand times
-- Notice the difference in runtime when using 11.1.0.7 or 11.2.0.1
declare
procedure check_key
as
x integer;
n_id integer;
s_vc varchar2(255);
begin
x := 42 * 3;
select
id
, vc
into
n_id
, s_vc
from
t_testloop
where
id = x;
exception
when NO_DATA_FOUND then
null;
end;
begin
for i in 1..1000 loop
check_key;
end loop;
end;
/

The crucial line is the one above containing "DBMS_XMLDOM.FREEDOCUMENT". If you run this script without the FREEDOCUMENT call on a version that is affected by the slow-down, like 11.1.0.7 or 11.2.0.1, then a typical output might look like the following:

SQL> declare
2 procedure check_key
3 as
4 x integer;
5 n_id integer;
6 s_vc varchar2(255);
7 begin
8 x := 42 * 3;
9 select
10 id
11 , vc
12 into
13 n_id
14 , s_vc
15 from
16 t_testloop
17 where
18 id = x;
19 exception
20 when NO_DATA_FOUND then
21 null;
22 end;
23 begin
24 for i in 1..1000 loop
25 check_key;
26 end loop;
27 end;
28 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.94

.
.
.

Run 1: Time (in seconds)= .49
Run 2: Time (in seconds)= .08
Run 3: Time (in seconds)= .08
Run 4: Time (in seconds)= .08
Run 5: Time (in seconds)= .05
Run 6: Time (in seconds)= .03
Run 7: Time (in seconds)= .03
Run 8: Time (in seconds)= .03
Run 9: Time (in seconds)= .03
Run 10: Time (in seconds)= .02
Run 11: Time (in seconds)= .03
Run 12: Time (in seconds)= .03
Run 13: Time (in seconds)= .03
Run 14: Time (in seconds)= .03
Run 15: Time (in seconds)= .03
Run 16: Time (in seconds)= .03
Run 17: Time (in seconds)= .02
Run 18: Time (in seconds)= .03
Run 19: Time (in seconds)= .03
Run 20: Time (in seconds)= .03
Run 21: Time (in seconds)= .03
Run 22: Time (in seconds)= .03
Run 23: Time (in seconds)= .03
Run 24: Time (in seconds)= .03
Run 25: Time (in seconds)= .03
.
.
.
Run 287: Time (in seconds)= .03
Run 288: Time (in seconds)= .03
Run 289: Time (in seconds)= .03
Run 290: Time (in seconds)= .03
Run 291: Time (in seconds)= .02
Run 292: Time (in seconds)= .03
Run 293: Time (in seconds)= .03
Run 294: Time (in seconds)= .03
Run 295: Time (in seconds)= .03
Run 296: Time (in seconds)= .03
Run 297: Time (in seconds)= .03
Run 298: Time (in seconds)= .02
Run 299: Time (in seconds)= .03
Run 300: Time (in seconds)= .03
Run 301: Time (in seconds)= .03
Run 302: Time (in seconds)= .03
Run 303: Time (in seconds)= .17
Run 304: Time (in seconds)= .17
Run 305: Time (in seconds)= .17
Run 306: Time (in seconds)= .17
Run 307: Time (in seconds)= .17
Run 308: Time (in seconds)= .17
Run 309: Time (in seconds)= .17
Run 310: Time (in seconds)= .17
Run 311: Time (in seconds)= .18
Run 312: Time (in seconds)= .17
Run 313: Time (in seconds)= .18
Run 314: Time (in seconds)= .18
Run 315: Time (in seconds)= .18
Run 316: Time (in seconds)= .17
Run 317: Time (in seconds)= .19
Run 318: Time (in seconds)= .18
Run 319: Time (in seconds)= .18
Run 320: Time (in seconds)= .19
Run 321: Time (in seconds)= .18
Run 322: Time (in seconds)= .19
.
.
.
Run 973: Time (in seconds)= .82
Run 974: Time (in seconds)= .83
Run 975: Time (in seconds)= .83
Run 976: Time (in seconds)= .82
Run 977: Time (in seconds)= .83
Run 978: Time (in seconds)= .83
Run 979: Time (in seconds)= .82
Run 980: Time (in seconds)= .82
Run 981: Time (in seconds)= .83
Run 982: Time (in seconds)= .82
Run 983: Time (in seconds)= .83
Run 984: Time (in seconds)= .83
Run 985: Time (in seconds)= .82
Run 986: Time (in seconds)= .84
Run 987: Time (in seconds)= .83
Run 988: Time (in seconds)= .86
Run 989: Time (in seconds)= .84
Run 990: Time (in seconds)= .83
Run 991: Time (in seconds)= .85
Run 992: Time (in seconds)= .84
Run 993: Time (in seconds)= .84
Run 994: Time (in seconds)= .85
Run 995: Time (in seconds)= .84
Run 996: Time (in seconds)= .85
Run 997: Time (in seconds)= .84
Run 998: Time (in seconds)= .87
Run 999: Time (in seconds)= .84
Run 1000: Time (in seconds)= .85

PL/SQL procedure successfully completed.

Elapsed: 00:06:00.49
SQL>
SQL> declare
2 procedure check_key
3 as
4 x integer;
5 n_id integer;
6 s_vc varchar2(255);
7 begin
8 x := 42 * 3;
9 select
10 id
11 , vc
12 into
13 n_id
14 , s_vc
15 from
16 t_testloop
17 where
18 id = x;
19 exception
20 when NO_DATA_FOUND then
21 null;
22 end;
23 begin
24 for i in 1..1000 loop
25 check_key;
26 end loop;
27 end;
28 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.02
SQL>

Notice how after a certain number of iterations the execution gets slower and slower. And what is even more interesting is that the simple loop of 1,000 SQL statement executions afterwards takes significantly longer than before the code block got executed.

You might want to monitor the PGA/UGA consumption in the Session Statistics or V$PROCESS and V$TEMPORARY_LOBS while the block is executing.

If you run the same in 10.2.0.4, you'll monitor the same symptoms, but the execution time will stay consistent, at least up to 1,000 iterations - obviously there will be a point where a system might get trouble with the ever increasing memory consumption, however that is not the point here.

If DBMS_XMLDOM.FREEDOCUMENT is called correctly then the same code block in 11.1.0.7 and 11.2.0.1 will also show consistent execution times (and no increased PGA/UGA memory or temporary LOBs).

Interestingly Nigel Noble also has recently published a blog note about PL/SQL memory issues that are only reproducible in 11.1.0.7 but don't show up in 10.2.0.4.

So although the issues reported by Alex Fatkulin and Nigel Noble aren't necessarily related to this one here, all this seems to suggest that Oracle release 11 introduced some changes to the way memory is managed (may be due to the introduction of Automatic Memory Management (AMM) and the memory_target parameter) that seem to behave differently than in previous releases under certain circumstances.

References:
Tanel Poder's Advanced Oracle Troubleshooting series
Advanced Oracle Troubleshooting
Tanel's posts on troubleshooting

Expert Oracle Practices from the OakTable, Chapter 8

Edition-Based Redefinition

Upgrading critical applications can be very difficult. One of the main problems is that for reasons of availability, long downtimes cannot be periodically scheduled. Therefore, for such applications, it is desirable to implement online upgrades. This requires that the application in question, as well as any software used by the application (e.g. the database engine) all support online upgrades. Oracle has recognized this problem for years. Unfortunately, up to and including Database 11g Release 1, only a limited number of features have been implemented for that purpose. As of Oracle Database 11g Release 2, this situation has changed greatly. With edition-based redefinition, Oracle Database offers real support for implementing online upgrades. The aim of this paper is to provide an overview of this new feature.
Download full article: http://antognini.ch/papers/EditionBasedRedefinition20101204.pdf