Monday, March 22, 2010

Demonstrate a function-based index is unable to be used due to cursor_sharing setting

rem  Demonstrate a function-based index is unable to be used
rem  due to cursor_sharing setting
rem
rem  The function is substr(col, 1,6), when cursor_sharing = 
rem  FORCE or SIMILAR, the literals, i,e, 1 and 6 are replaced 
rem  by system-generated variables. This may casued mis-match 
rem  against the index definition
rem
rem  When we use autotrace to check the exection plan,
rem  we do see the index is used; however, at run time, this is 
rem  not the case as shown by 10046 trace. 
rem
rem  Test env: 9.2.0.8 

set echo on
spool fun_idx

drop table t;
create table t as
select rownum id,
       object_name name,
       rpad('x',8) val
from all_objects 
where rownum <=2000;

create index t_idx on t(substr(name, 1,6));
exec dbms_stats.gather_table_stats(user,'t', cascade=>true);

select * from v$version;

alter session set tracefile_identifier=fun;
alter session set timed_statistics=true;
alter session set events '10046 trace name context forever, level 12';

alter session set cursor_sharing=force;
select /* force */ * 
from t 
where substr(name,1,6)='ABCDEF';

alter session set cursor_sharing=similar;
select /* similar */ * 
from t 
where substr(name,1,6)='ABCDEF';

alter session set cursor_sharing=exact;
select /* exact */ * 
from t 
where substr(name,1,6)='ABCDEF';

exit;


set doc off
doc

--- force  ----

select /* force */ *
from t
where substr(name,:"SYS_B_0",:"SYS_B_1")=:"SYS_B_2"
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         13          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         13          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL T

--- similar ----
 
select /* similar */ *
from t
where substr(name,:"SYS_B_0",:"SYS_B_1")=:"SYS_B_2"
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         13          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.00          0         13          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL T

--- exact ---

select /* exact */ *
from t
where substr(name,1,6)='ABCDEF'
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          2          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 183
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS BY INDEX ROWID T
      0   INDEX RANGE SCAN T_IDX (object id 224130)
# 



May 11, 2010 updated: Original post ended at the previous line, all below is added today:

I was pinged by one of my colleagues the other day saying "Jonathan Lewis referred to your blog". I was surprized to hear that. Then I found out that Coskan first included this post in his blog , then Jonathan mentioned it in one of his blog posts (footnote section), which describes the same issue but of course includes deeper technical insights. I regarded Jonathan as my mentor secretly :-). First of all, I learned a lot from his blog and website, and his book "Cost-based Oracle Fundenmental" as well. In my LinkedIn profile "Reading List by Amazon" section, I commented "I read it through when I was on bench in Fall 2007. Even 20% of understanding of it helped me gain some respect from app team and peer DBAs by showing I was able to tune sqls . I will read it again and again utill fully digest it hopefully one day. " Secondly, I once listened to a podcast of his interview with DBAZine, in which he emphasized how the approach of building test cases can help one become better DBA or troubleshooter. I kept this in mind and have been trying practise this tip always. The test case I showed  in this post is a proof :-). The style of this test case is actually somewhat mimicing the code examples of the above mentioned book. Especially the "set doc off" syntax, which I did not know until I read his book.

This test case was resulted from my trouble-shooting experience for a real production issue at the posting date. A production database  server CPU utilization reached 100% from time to time from the morning and some jobs were slower than normal. Top SQL during the problem period was an update statement, supposedly using a function-based index. I was called by a fellow DBA to check why full table scan was actually used instead. From the shared pool, we knew it has been executed by FTS .

My favorite tool to check the execution plan at the first round is Autotrace :

** Autotrace showing index scan but consistent gets = 148626

myusrid@MYPRDDB1> set autotrace traceonly
myusrid@MYPRDDB1> select * from
2 XYZ_UVW.ABC_ABCDEFG_ABCDEF_ABCDEF
3 WHERE substr(DEPENDANT_ORDER,1,13) = '123456789012'
4 ;

o rows selected

ecution Plan
---------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=18 Bytes=1494)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'ABC_ABCDEFG_ABCDEF_ABCDEF' (Cost=4 Card=18 Bytes=1494)
2 1 INDEX (RANGE SCAN) OF 'ABC_ABCDEFG_ABCDEF_ABCDE_IDX5N' (NON-UNIQUE) (Cost=Card=1)


statistics
---------------------------------------------------------
0 recursive calls
0 db block gets
148626 consistent gets
135926 physical reads
0 redo size
490 bytes sent via SQL*Net to client
229 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed


I knew parse-time execution plan could be different from run-time. So from Autotrace, I confirmed index scan was considered favarable, however from the "consistent gets", I knew at run time Oracle did FTS as it matched stackpack "Gets per Execution":


** From statspack during problem period, Gets Per Exec = 149314

Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
98,995,283 663 149,314.2 49.0 ######## 10769.86 3803649956
Module: JDBC Thin Client
UPDATE ABC_ABCDEFG_ABCDEF_ABCDEF SET DEPENDANT_ORDER =:1 WHERE S
UBSTR(DEPENDANT_ORDER,:"SYS_B_0",:"SYS_B_1") =:2

It took me quite a while to realize what happened was due to CURSOR_SHARING setting:

** Autotrace showing index scan and consistent gets = 3 after seting cursor_sharing=exact

myusrid@MYPRDDB1> alter session set cursor_sharing=exact;

Session altered.

myusrid@MYPRDDB1> select * from
2 XYZ_UVW.ABC_ABCDEFG_ABCDEF_ABCDEF
3 WHERE substr(DEPENDANT_ORDER,1,13) = '123456789012'
4 ;

no rows selected


Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE (Cost=4 Card=18 Bytes=1494)
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'ABC_ABCDEFG_ABCDEF_ABCDEF' (Cost=4 Card=18 Bytes=1494)
2 1 INDEX (RANGE SCAN) OF 'ABC_ABCDEFG_ABCDEF_ABCDE_IDX5N' (NON-UNIQUE) (Cost=3 Card=1)


Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
2 physical reads
0 redo size
490 bytes sent via SQL*Net to client
229 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed


I took a brave step to solve the prodution issue as during the middle of the day code change was not possible and also it was subjected to some change management processes in my working envrionment. I told the development team, I was going to change CURSOR_SHARING from FORCE to EXACT in the production database as an emergent performance stablizing measure ( as this change should be subjected to change management process too), and if we saw problems after the change, I would revert it back and they still needed to plan code change to fix that update statment (Dev think they should have used bind variables appropriately, but no one could really gurantee this change would not cause other more serious problems). So I changed it to EXACT, so far so good.

No comments: