Rolling invalidations Addendum

If you enable cursor trace for the testcase in my previous post using the method described in http://el-caro.blogspot.com/search?q=unshared

The generated trace in udump will have the following

************************************************************
kksCheckCursor: pinning child #0 in shared mode 7d42bd0e8 7d7e87600
Failed sharing : Rolling invalidation
kksUnlockChild: releasing child
Failed sharing : 800000000000
kksSearchChildList: no suitable child found
Creating new child object #1
kksLoadChild: reload 0 child_reload 0
kksLoadChild: reload 0 child_reload 0
Compilation environment difference Failed sharing : 0
Change in cursor environment
************************************************************

Also the parameter _optimizer_invalidation_period does not work for statements using PQ. This can be tested by changing the degree of the table to 4 (say) and running the same test. In this case a new child cursor is generated on the first re-execution of the statement after stats are gathered even when the auto_invalidate flag is used.

Diagnosing unshared SQL in 10g

One of the ways to increase scalability and throughput of an application is to see to it that SQL statements are shared and reduce the number of children of sql statements. In versions prior to 10g the view V$SQL_SHARED_CURSOR would aid in diagnosing why sql statements were not being shared.In 10g there is a new event called CURSORTRACE which aids in the same.

Let us take the following simple sql statement.

SESSION1>> select count(*) from dept;

COUNT(*)
----------
4

SESSION1>> select sql_text, hash_value,address from v$sqlarea where sql_text like 'select count(*) from dept%';

SQL_TEXT HASH_VALUE ADDRESS
----------------------------------- ---------- --------
select count(*) from dept 761178024 19156098

This the first child of the above sql statement with all 'N's

SESSION1>> select * from v$sql_shared_cursor where address = '19156098';

SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - -
R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
1jrz3ucqpx9x8 19156098 1CEFB584 0 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N

Now let us open a new session and issue the above sql statement but see to it that the cursor is not shared

SESSION2>>alter session set optimizer_mode='RULE';

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

Check from Session 1 how many children have been generated
SESSION1>>select * from v$sql_shared_cursor where address = '19156098';

SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - -
R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
1jrz3ucqpx9x8 19156098 1CEFB584 0 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N

1jrz3ucqpx9x8 19156098 1BA90164 1 N N N N N N N N N N N N N N N N N N
N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N Y N N N N

As expected we have one more child caused by the OPTIMIZER_MODE_MISMATCH which we
forced.

SESSION2>>alter session set events 'immediate trace name cursortrace level 612, address 761178024';

==> 761178024 is the hash value of the sql statement.

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

SESSION2>>alter session set optimizer_mode='FIRST_ROWS_1';

Session altered.

SESSION2>>select count(*) from dept;

COUNT(*)
----------
4

The resultant trace file generated in user_dump_dest will throw more
light into why the sql statement is not shared.

Here is a snippet from the trace file

*************************************************************************
PARSING SQLTEXT=select count(*) from dept
SQLHASH=2d5ea7a8
Checking for already pinned child.
No valid child pinned
Parent 1EA853E8(19156098) ready for search
kksSearchChildList outside while loop
kksCheckCursor: next child is #1
kksCheckCursor: pinning child #1 in shared mode 1eb62650 1ba90164
Compilation environment difference Failed sharing : 0
optimizer_mode = first_rows_1 rule
sqlstat_enabled = false true
SQL pgadep:0 pgapls:0 user
Failed sharing : Compilation environment mismatch
kksUnlockChild: releasing child
*************************************************************************

Disabling cursor trace

Sometime last year I had blogged about unshared cursors and an event to trace the same here
http://el-caro.blogspot.com/search?q=cursor+trace


Well after you set the trace on and have got the required information you would obviously want to turn it off.

The command to do the same is

alter system set events 'immediate trace name cursortrace level 2147483648, addr 1';

However this does not work as I realized today when I was diagnosing multiple versions created for pl/sql procedure calls with ref cursors as arguments and the trace almost filled up my udump. New sessions spawned have entries such as the below
for any cursor executed.

CUR#2 XSC 0xxxxxxxx CHILD#0 CI 0xxxxxxx CTX (nil)

To fix this issue you need to apply the fix for unpublished bug

5555371 NO WAY TO TURN OFF TRACE AFTER SETTING CURSORTRACE EVENT

on top of 10.2.0.x

Another way to disable the trace would be to restart the instance.