01 March 2007
Cursortrace event
It is interesting to see how tuning unfolds. For example, I noticed that few SQL statements were running slow. Trace showed they were being re-parsed almost every time they ran. After investigating further, I found that there was a large number of loaded versions in SQL area. Specific SQLs were occupying more than 90% of the SQL area. v$shared_cursor was showing "N" for all columns.
This is a typical case for the cursor_sharing=SIMILAR, where SQL commands are shared only if the incoming literal values are the same. It can be fixed by removing the histograms from the non-skewed columns, especially from the columns with equal predicates. Funnily, I used "AUTOSKEW" option to create histograms, but they were obviously created on the columns which were not skewed, like Employee ID and Effective Date.
CURSORTRACE commands
CURSORTRACE command is good for finding out why the children cursors are not shared with their parents. This was the first time I heard about CURSORTRACE event, so I Google-d it.There were only few entries on the Internet, plus I couldn't find the syntax of disabling the cursor tracing, so I am publishing it here.
In general, CURSORTRACE looks like an old event 10270.
I found on Metalink that levels 612 and 577 are commonly used for tracing.
612 trace had only 1 extra line in my trace file, but I flushed the cursors before running 612, so it is possible that line is not an indicator of their difference:
SQL> select count(*) from tanya where a>0;
COUNT(*)
----------
3036045
SQL> select hash_value, sql_text from v$sql where sql_text like 'select count(*) from tanya where%'
HASH_VALUE SQL_TEXT
---------- ------------------------------------------------------------
1015025251 select count(*) from tanya where a>:"SYS_B_0"
SQL > alter session set events 'immediate trace name cursortrace level 612, address 1015025251';
Session altered.
-- The optimizer environment will prompt Oracle to spawn another child.
SQL>alter session set optimizer_index_cost_adj=50;
Session altered.
SQL> select count(*) from tanya where a>1444555;
COUNT(*)
----------
876583
Here is what shows up in the udump trace file:
====================
PARSING IN CURSOR #11 len=45 dep=0 uid=0 oct=42 lid=0 tim=15105813770667 hv=3940405228 ad='eeb6a190'
alter session set optimizer_index_cost_adj=50
END OF STMT
PARSE #11:c=10000,e=8495,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=15105813770644
EXEC #11:c=0,e=1254,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=15105813772255
*** 2007-03-01 11:21:37.518
CUR#12 XSC ffffffff7b0adc20 CHILD#-1 CI 0 CTX 0
PARSING SQLTEXT=select count(*) from tanya where a>:"SYS_B_0"
SQLHASH=3c800e63
Checking for already pinned child.
No valid child pinned
Parent 3e9d2c318(3ea35ba70) ready for search
kksSearchChildList outside while loop
kksSearchChildList: no suitable child found
Creating new child object #2
Compilation environment difference Failed sharing : 0
sqlstat_enabled = false true
Change in cursor environment
SQL pgadep:0 pgapls:0 system
Child creation successful 3eea1c8e8 3e9261bb8 0
====================
Quite nice ! I only wish I could see exactly what environment parameter was changed to initiate the creation of child cursor. Oracle analyst told me that, somehow, this meant the "unsafe bind", which is related to the mentioned cursor_sharing.
References: Metalink note 2963771.1, Metalink bug 5406524, Metalink bug 5545550
This is a typical case for the cursor_sharing=SIMILAR, where SQL commands are shared only if the incoming literal values are the same. It can be fixed by removing the histograms from the non-skewed columns, especially from the columns with equal predicates. Funnily, I used "AUTOSKEW" option to create histograms, but they were obviously created on the columns which were not skewed, like Employee ID and Effective Date.
CURSORTRACE commands
CURSORTRACE command is good for finding out why the children cursors are not shared with their parents. This was the first time I heard about CURSORTRACE event, so I Google-d it.There were only few entries on the Internet, plus I couldn't find the syntax of disabling the cursor tracing, so I am publishing it here.
In general, CURSORTRACE looks like an old event 10270.
- To enable it:
- alter system set events 'immediate trace name cursortrace level 612, address &hashvalue'
- &hashvalue is the hash_value from v$sql.
- To disable it:
- alter system set events 'immediate trace name cursortrace level 128, address &hashvalue'
- I noticed that if I put some non-existing address, like "alter system... level 612, address 1'" the tracing for the specific cursor stops. This points to the fact that system can trace only 1 cursor at a time. I would still not use this method to stop the tracing, as level 128 looks like a proper option.
I found on Metalink that levels 612 and 577 are commonly used for tracing.
612 trace had only 1 extra line in my trace file, but I flushed the cursors before running 612, so it is possible that line is not an indicator of their difference:
- kksfbc: child #6 is broken
SQL> select count(*) from tanya where a>0;
COUNT(*)
----------
3036045
SQL> select hash_value, sql_text from v$sql where sql_text like 'select count(*) from tanya where%'
HASH_VALUE SQL_TEXT
---------- ------------------------------------------------------------
1015025251 select count(*) from tanya where a>:"SYS_B_0"
SQL > alter session set events 'immediate trace name cursortrace level 612, address 1015025251';
Session altered.
-- The optimizer environment will prompt Oracle to spawn another child.
SQL>alter session set optimizer_index_cost_adj=50;
Session altered.
SQL> select count(*) from tanya where a>1444555;
COUNT(*)
----------
876583
Here is what shows up in the udump trace file:
====================
PARSING IN CURSOR #11 len=45 dep=0 uid=0 oct=42 lid=0 tim=15105813770667 hv=3940405228 ad='eeb6a190'
alter session set optimizer_index_cost_adj=50
END OF STMT
PARSE #11:c=10000,e=8495,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=15105813770644
EXEC #11:c=0,e=1254,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=15105813772255
*** 2007-03-01 11:21:37.518
CUR#12 XSC ffffffff7b0adc20 CHILD#-1 CI 0 CTX 0
PARSING SQLTEXT=select count(*) from tanya where a>:"SYS_B_0"
SQLHASH=3c800e63
Checking for already pinned child.
No valid child pinned
Parent 3e9d2c318(3ea35ba70) ready for search
kksSearchChildList outside while loop
kksSearchChildList: no suitable child found
Creating new child object #2
Compilation environment difference Failed sharing : 0
sqlstat_enabled = false true
Change in cursor environment
SQL pgadep:0 pgapls:0 system
Child creation successful 3eea1c8e8 3e9261bb8 0
====================
Quite nice ! I only wish I could see exactly what environment parameter was changed to initiate the creation of child cursor. Oracle analyst told me that, somehow, this meant the "unsafe bind", which is related to the mentioned cursor_sharing.
References: Metalink note 2963771.1, Metalink bug 5406524, Metalink bug 5545550
