Oraclue

Oracle internals, debugging and undocumented features

Cursor high_version count Part 1

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

 and turn  cursor tracing off
alter system set events 'immediate trace name cursortrace level 2147483648, address 1';
Why cursor has so many different versions in my case ( not test case )? 
Next post.. 
 
 
 
 

 

Advertisements

3 responses to “Cursor high_version count Part 1

  1. chet December 3, 2008 at 3:14 am

    so explain what all that means to us lower life forms please. 😉

  2. Martin Berger December 3, 2008 at 7:59 pm

    is there anything behind the
    Compilation environment difference Failed sharing : 0
    in the first trace? something like
    Failed sharing : Compilation environment mismatch
    or Change in cursor environment?
    … waiting for the sequel.

  3. oraclue December 3, 2008 at 8:13 pm

    Yes.I did only first part of the trace.Here is the part that you are looking for:

    Cursor#3 mapped
    Compilation environment difference Failed sharing : 0
    Change in cursor environment
    SQL pgadep:0 pgapls:0 user
    Compilation environment difference Failed sharing : 0
    Change in cursor environment
    SQL pgadep:0 pgapls:0 user
    Child creation successful 0xbb8f88c0 0xc3637818 0
    Checking for already pinned child. fbcflg 102
    kkssbt: setting types
    kkssbt: opitca 0xbefc8f70 0xbdb09af8
    Compilation environment difference Failed sharing : 0
    Change in cursor environment
    SQL pgadep:0 pgapls:0 user

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: