Miladin Modrakovic's Blog: Oraclue

The sql query was using a lot of CPU’s resources.Research shows that cursor has high version_count. It is not being shared because of bind mismatch.

So for troubleshooting I have used  CURSORTRACE to trace cursor and get more information why cursor is not being shared. 

Some basic informations and simple test case :

Command to start tracing:

alter system set events ‘immediate trace name cursortrace level 577, address hash_value’;

where hash_value  is comming from v$sqlarea .

from oracle documentation (level 578/580 can be used for high level tracing (577=level 1, 578=level 2, 580=level 3)

This will write a trace file each time we try to reuse the cursor.

Command to turn off tracing

alter system set events ‘immediate trace name cursortrace level 2147483648, address 1′;

alter system set events  ‘immediate trace name cursortrace level 2147483648, address <hash_value>’;

alter session set events ‘immediate trace name cursortrace level 128 , address <address>’;

In 10g there is a bug BUG5555371 and you cannot turn off tracing.You have to bounce instance to stop it.

e.g. 

alter session set cursor_sharing=similar;

select /* MYTEST */ * from emp where sal > 100;
select /* MYTEST */ * from emp where sal > 101;
select /* MYTEST */ * from emp where sal > 102;
select /* MYTEST */ * from emp where sal > 103;
select /* MYTEST */ * from emp where sal > 104;

Of course this will produce five different versions:

SQL> set linesize 156
col sql_text format a67
SELECT sql_text,version_count,address,hash_value
FROM V$SQLAREA
WHERE sql_text like ‘select /* MYTEST */%’;

SQL_TEXT                                                                VERSION_COUNT    ADDRESS                     HASH_VALUE
——————————————————————- ————-
select /* MYTEST */ * from emp where sal > :”SYS_B_0″                   5     00000000BB90D9F0  1774150224

Enable tracing:

alter system set events ‘immediate trace name cursortrace level 577, address 1774150224′;

and here is a part of a trace file where we can see all details:

CUR#3 XSC 0x2aaaac09c380 CHILD#-1 CI (nil) CTX (nil)
 PARSING SQLTEXT=select /* MYTEST */ * from emp where sal > :”SYS_B_0″
 SQLHASH=f3364dc0
 Checking for already pinned child. fbcflg 108
 No valid child pinned
 Parent 0xc39ed410(0xbb90d9f0) ready for search
 kksSearchChildList outside while loop
 kksSearchChildList: no suitable child found
 Creating new child object #0
 kksLoadChild: reload 0 child_reload 0
 kksLoadChild: reload 0 child_reload 0
 Compilation environment difference Failed sharing : 0

Now let’s swithc to cursor=exact and trace it so we can compare trace files:

 cursor=exact :

SQL> SELECT sql_text,version_count,address,hash_value
FROM V$SQLAREA
WHERE sql_text like ‘select /* MYTEST */%’;  2    3

SQL_TEXT                                VERSION_COUNT ADDRESS          HASH_VALUE
——————————————————————- ————–
select /* MYTEST */ * from emp where sal > 102       1 00000000C39E60E0 1691629829
select /* MYTEST */ * from emp where sal > 100       1 00000000C39BD4D8 4080422336
select /* MYTEST */ * from emp where sal > 101       1 00000000BBAB4D28 1447794777
select /* MYTEST */ * from emp where sal > 104       1 00000000C37D4320 1672716934
select /* MYTEST */ * from emp where sal > 103       1 00000000C33B17E0 3109268566

Now we got version_count=1

Let’s pick one of these :

SQL> alter system set events ‘immediate trace name cursortrace level 577, address 1691629829′;

and note difference in trace file:

CUR#7 XSC 0x2aaaac0993f8 CHILD#-1 CI (nil) CTX (nil)
 PARSING SQLTEXT=select /* MYTEST */ * from emp where sal > 102
 SQLHASH=64d43905
 Checking for already pinned child. fbcflg 108
 No valid child pinned
 Parent 0xc344f778(0xc39e60e0) ready for search
 kksSearchChildList outside while loop
 kksCheckCursor: next child is #0
 kksCheckCursor: pinning child #0 in shared mode 0xbbe854d0 0xbbeab9b8
 Calling for auth
 Succeed sharing : child#0
 Checking for already pinned child. fbcflg 102
 Cursor about get executed
 Checking for already pinned child. fbcflg 1
 Cursor#7 mapped
 Cursor unmapped
CUR#7 XSC 0x2aaaac0993f8 CHILD#0 CI 0xbebf0d80 CTX (nil)
 Cursor#7 mapped
 Closing cursor