SQL Tuning

Things I think important to know for sql tuning:

• Be able to read execution plan

         - right-most first, from top to bottom
         - visual approach to assist understanding   
         - pay attention to the Predicate Information section

• Obtaining the execution plan

         - AUTOTRACE 
         - dbms_xplan.display_curosr

• Cardinality

         - the predicted number of rows generated by an operation
         - cardinality = selectivity * ( number of input rows)

• COST

         - represent the optimizer's best estimate of the time it will take to execute the statement; CBO always chooses the execution plan with minimum cost.

• Tuning by cardinality feedback

         - using dbms_xplan.display_cursor to obtain E-row vs A-row ( set statistical_level=all;  or using /* gather_plan_statistics */ )

• AWR, ADDM, ASH and wait interface - able to identify the offensive SQLs
• bind variable peeking and plan instability
• 10046 trace & tkprof

         - a rule of thumb to check efficiency: query+ current/rows < 20

• 10053 trace
• join method and join order
• Able to check table indexes and table column statistics ( HISTOGRAM)
• Using top-n query to show the data distribution

         ie.  select * from ( select col_of_insterest,count(*) from table_A group by col_of_interest order by 2 desc) where rownun <=50

• Talk to lead developers

         - tune questions not just tune queries

• Fix a bad query or method of improvement

        - index re-design,
        - hints,
        - gather stats,
        - explore parallelism,
        - plan stability: sql profile( sqlt coe* script) and sql plan baseline (sqlt coe* script)

Why 11g chooses the access path of index scan with inlist as filter?

In a previous post ( http://oracle-study-notes.blogspot.com/2012/07/using-sql-plan-baseline-to-ensure-10g.html), I described that a SQL performed badly after upgrade from 10g to 11g due to the change of execution plan and I used "SQL Plan Baseline" feature to force the sql executing with the good plan. The bad plan uses "inlist as filter" in an index scan access path. In this post I will try to understand why the execution plan changed from 10g to 11g. To simplify the investigation, I only explored a single table access query shown as follows:

select fds_seq,order_id 
from  fds
where
     fds.status IN ( 'LD', 'RT' )  
and  fds.thread_id = '1'  
;

In this query, the table fds is created from the production table by CTAS and it has only one index fds_ix1 on (thread_id,status). After upgrade to 11g, we used the same statistics gathering script as in 10g. I collected the stats for table fds using the same options as those in the 11g or 10g database:

exec dbms_stats.gather_table_stats(user,'FDS',method_opt => 'FOR ALL COLUMNS SIZE 1', estimate_percent =>10, cascade => TRUE,degree => 4) ;

The column statistics of this table is shown below:

COLUMN_NAME                      DISTINCT DENSITY      NULLS BKTS LO               HI
------------------------------ ---------- ------- ---------- ---- ---------------- ----------------
FDS_SEQ                         101188250   0.000          0    1          2756031        109967122
ORDER_ID                         19009758   0.000   49654490    1 CADX010101010    RMOG293464421,CM
RETRY_COUNT                            48   0.021  100892510    1 1                9
STATUS                                 14   0.071          0    1 DD               XX
THREAD_ID                           46932   0.000          0    1 0                bnscqpa4+9999
TIMESTAMP                        22878788   0.000          0    1 27-DEC-2004      23-JUL-2012

In the 11g (11.2.0.3) database, the execution plan of the query and execution statistics are obtained from AUTOTRACE:

Execution Plan
----------------------------------------------------------
Plan hash value: 137039772

---------------------------------------------------------------------------------------
| Id  | Operation                   | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |  4312 |   101K|    63   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| FDS     |  4312 |   101K|    63   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | FDS_IX1 |  2224 |       |    10   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("FDS"."THREAD_ID"='1')
       filter("FDS"."STATUS"='LD' OR "FDS"."STATUS"='RT')


Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
     153373  consistent gets
     153361  physical reads
          0  redo size
      19755  bytes sent via SQL*Net to client
        294  bytes received via SQL*Net from client
          8  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        696  rows processed

By looking at the the Predicate Information section, we can know that Oracle chooses "inlist as filiter" access path. I also created the same FDS table in a 10g (10.2.0.4) database and analyzed it with same option. The columns stats shown as follows:

COLUMN_NAME                      DISTINCT DENSITY      NULLS BKTS LO               HI
------------------------------ ---------- ------- ---------- ---- ---------------- ----------------
FDS_SEQ                         101182940   0.000          0    1          2756031        109967120
ORDER_ID                         19024012   0.000   49606920    1 CADX010101010    RMOG292175979,CM
RETRY_COUNT                            47   0.021  100889040    1 1                9
STATUS                                 14   0.071          0    1 DD               XX
THREAD_ID                           46926   0.000          0    1 0                bnscqpa4+9999
TIMESTAMP                        22875629   0.000          0    1 27-DEC-2004      23-JUL-2012

It can be seen that the column statistics of the table is almost identifical in 10g and 11g. However, the AUTOTRACE report in the 10g database shows the different execution plan and much less gets-per-execution value (132 vs 153373)

Execution Plan
----------------------------------------------------------
Plan hash value: 3825939584

----------------------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |   308 |  7392 |    13   (0)| 00:00:01 |
|   1 |  INLIST ITERATOR             |         |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| FDS     |   308 |  7392 |    13   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | FDS_IX1 |   315 |       |     5   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("FDS"."THREAD_ID"='1' AND ("FDS"."STATUS"='LD' OR
              "FDS"."STATUS"='RT'))


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        132  consistent gets
        105  physical reads
          0  redo size
       8924  bytes sent via SQL*Net to client
        289  bytes received via SQL*Net from client
          8  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        696  rows processed

I did 10053 traces for the query in 10g and 11g database respectivly. The 10053 trace excerpts are shown in Appendix. It can be seen that Oracle CBO evaluated both execution plans in 10g and 11g. The following table gives the cost of each plan in 10g and 11g as seen in the trace

------------------------------------------------------
Plan        Index scan with           Index scan with  
            inlist as filter          INLIST ITERATOR
------------------------------------------------------
10.2.0.4           18.00                      13.03 
11.2.0.3           63.27                     122.30 
-------------------------------------------------------

Based on the cost value, it is easy to understand that 10g and 11g choose different plans as their "best" plan. By comparing the 10053 trace, I think one key difference that leads to the different cost values lies in the index selectivity of the two-column index FDS_IX1. Index selectivity: FDS_IX1 on (thread_id, status )

------------------------------------------------------------------------------
Plan        Index  selectivity           #DK of        NDV of            NDV of
                                        Index         thread_id         status
-------------------------------------------------------------------------------
10.2.0.4         3.0443e-06              46926          46926             14 
11.2.0.3           0.000043              46932          46932             14
------------------------------------------------------------------------------

In 10g: index selectivity = (1/46926 ) * (1/14) *2 = 3.0443e-06 In 11g: index selectivity = (1/46932 ) * 2 = 0.0000043 It shows that Oracle uses different the formula to calculate the two-column index selectivity. In 10g the selectivity is based on 1/num_distinct for the two columns; while in 11g 1/distinct_keys for the index. I believe this difference on index selectivity explains the execution plan changes from 10g to 11g in this particular case, especially we use same stats gathering option in  11g as in 10g ( i.e. no histogram)

Appendix - 10053 trace:

-- script 
alter session set events '10053 trace name context forever';

explain plan for
select fds_seq,order_id 
from  fds
where
     fds.status IN ( 'LD', 'RT' )  
and  fds.thread_id = '1'  
;

alter session set events '10053 trace name context off';


---- from  a 10g database -----------

*****************************
SYSTEM STATISTICS INFORMATION
*****************************
  Using NOWORKLOAD Stats
  CPUSPEED: 765 millions instruction/sec
  IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
  IOSEEKTIM: 10 milliseconds (default is 10)
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: FDS  Alias: FDS
    #Rows: 101182940  #Blks:  499443  AvgRowLen:  31.00
Index Stats::
  Index: FDS_IX1  Col#: 5 2
    LVLS: 3  #LB: 285370  #DK: 46926  LB/K: 27.00  DB/K: 223.00  CLUF: 2337470.00
***************************************
SINGLE TABLE ACCESS PATH
  -----------------------------------------
  BEGIN Single Table Cardinality Estimation
  -----------------------------------------
  Column (#2): STATUS(CHARACTER)
    AvgLen: 3.00 NDV: 14 Nulls: 0 Density: 0.071429
  Column (#5): THREAD_ID(VARCHAR2)
    AvgLen: 6.00 NDV: 46926 Nulls: 0 Density: 2.1310e-05
  Table: FDS  Alias: FDS
    Card: Original: 101182940  Rounded: 308  Computed: 308.03  Non Adjusted: 308.03
  -----------------------------------------
  END   Single Table Cardinality Estimation
  -----------------------------------------
  Access Path: TableScan
    Cost:  112728.85  Resp: 112728.85  Degree: 0
      Cost_io: 109255.00  Cost_cpu: 31889016166
      Resp_io: 109255.00  Resp_cpu: 31889016166
  Access Path: index (RangeScan)
    Index: FDS_IX1
    resc_io: 13.00  resc_cpu: 249823
    ix_sel: 3.0443e-06  ix_sel_with_filters: 3.0443e-06
    Cost: 13.03  Resp: 13.03  Degree: 1
  Considering index with inlist as filter
  Access Path: index (RangeScan)
    Index: FDS_IX1
    resc_io: 18.00  resc_cpu: 794233
    ix_sel: 2.1310e-05  ix_sel_with_filters: 3.0443e-06
    Cost: 18.09  Resp: 18.09  Degree: 1
  Rejected inlist as filter
  ****** trying bitmap/domain indexes ******
  ****** finished trying bitmap/domain indexes ******
  Best:: AccessPath: IndexRange  Index: FDS_IX1
         Cost: 13.03  Degree: 1  Resp: 13.03  Card: 308.03  Bytes: 0
***************************************



--- from a 11g database ----------------

-----------------------------
SYSTEM STATISTICS INFORMATION
-----------------------------
  Using NOWORKLOAD Stats
  CPUSPEEDNW: 769 millions instructions/sec (default is 100)
  IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
  IOSEEKTIM:  10 milliseconds (default is 10)
  MBRC:       NO VALUE blocks (default is 16)
 
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: FDS  Alias: FDS
    #Rows: 101188250  #Blks:  500926  AvgRowLen:  32.00  ChainCnt:  0.00
Index Stats::
  Index: FDS_IX1  Col#: 5 2
    LVLS: 3  #LB: 290350  #DK: 46932  LB/K: 27.00  DB/K: 228.00  CLUF: 2450470.00
Access path analysis for FDS
***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for FDS[FDS]
  Column (#2): STATUS(
    AvgLen: 3 NDV: 14 Nulls: 0 Density: 0.071429
  Column (#5): THREAD_ID(
    AvgLen: 6 NDV: 46932 Nulls: 0 Density: 0.000021
  ColGroup (#1, Index) FDS_IX1
    Col#: 2 5    CorStregth: 14.00
  ColGroup Usage:: PredCnt: 2  Matches Full: #1  Partial:  Sel: 0.0000
  Table: FDS  Alias: FDS
    Card: Original: 101188250.000000  Rounded: 4312  Computed: 4312.12  Non Adjusted: 4312.12
  Access Path: TableScan
    Cost:  113037.39  Resp: 113037.39  Degree: 0
      Cost_io: 109579.00  Cost_cpu: 31901063983
      Resp_io: 109579.00  Resp_cpu: 31901063983
  ColGroup Usage:: PredCnt: 2  Matches Full: #1  Partial:  Sel: 0.0000
  ColGroup Usage:: PredCnt: 2  Matches Full: #1  Partial:  Sel: 0.0000
  Access Path: index (RangeScan)
    Index: FDS_IX1
    resc_io: 122.00  resc_cpu: 2803250
    ix_sel: 0.000043  ix_sel_with_filters: 0.000043
    Cost: 122.30  Resp: 122.30  Degree: 1
  Considering index with inlist as filter
 
  ColGroup Usage:: PredCnt: 2  Matches Full: #1  Partial:  Sel: 0.0000
  Access Path: index (RangeScan)
    Index: FDS_IX1
    resc_io: 63.00  resc_cpu: 2477875
    ix_sel: 0.000021  ix_sel_with_filters: 0.000021

 ***** Logdef predicate Adjustment ******
 Final IO cst 0.00 , CPU cst 0.00
 ***** End Logdef Adjustment ******
    Cost: 63.27  Resp: 63.27  Degree: 1
  Accepted inlist as filter
  ****** trying bitmap/domain indexes ******
  ****** finished trying bitmap/domain indexes ******
  Best:: AccessPath: IndexRange
  Index: FDS_IX1
         Cost: 63.27  Degree: 1  Resp: 63.27  Card: 4312.12  Bytes: 0
 
***************************************

Notes:
(1) In 11g, by fooling CBO through setting column stats manually, I am able to get the 10g access path with much better gets per execution:

Execution Plan
----------------------------------------------------------
Plan hash value: 3825939584

----------------------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |  4040 | 96960 |   119   (0)| 00:00:02 |
|   1 |  INLIST ITERATOR             |         |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| FDS     |  4040 | 96960 |   119   (0)| 00:00:02 |
|*  3 |    INDEX RANGE SCAN          | FDS_IX1 |  4229 |       |    15   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("FDS"."THREAD_ID"='1' AND ("FDS"."STATUS"='LD' OR
              "FDS"."STATUS"='RT'))


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        132  consistent gets
        104  physical reads
          0  redo size
      19755  bytes sent via SQL*Net to client
        294  bytes received via SQL*Net from client
          8  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        696  rows processed

(2)If we re-write the original query with UNION ALL, we also obtain a much better execution plan:

SQL> select fds_seq,order_id
  2  from  fds
  3  where
  4       fds.status IN ( 'LD' )
  5  and  fds.thread_id = '1'
  6  union all
  7  select fds_seq,order_id
  8  from fds
  9  where
 10       fds.status IN ('RT' )
 11  and  fds.thread_id = '1'
 12  ;

696 rows selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 3716244554

----------------------------------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |  4040 | 96960 |   122  (50)| 00:00:02 |
|   1 |  UNION-ALL                   |         |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| FDS     |  2020 | 48480 |    61   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | FDS_IX1 |  2115 |       |     9   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| FDS     |  2020 | 48480 |    61   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | FDS_IX1 |  2115 |       |     9   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("FDS"."THREAD_ID"='1' AND "FDS"."STATUS"='LD')
   5 - access("FDS"."THREAD_ID"='1' AND "FDS"."STATUS"='RT')


Statistics
----------------------------------------------------------
         21  recursive calls
          0  db block gets
        156  consistent gets
        108  physical reads
          0  redo size
       8851  bytes sent via SQL*Net to client
        294  bytes received via SQL*Net from client
          8  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
        696  rows processed

(3) In the 11g database, under some circumstances when gathering table stats, there could probably be histograms on the columns and Oracle could generate optimal execution plan in this case. (I did observe in one case when played around stats gathering on the FDS table)

Using SQL Plan Baseline to ensure a 10g execution plan after upgrade to 11g

Recently I have got a chance to use the SQL Plan Management feature - SQL Plan Baseline to fix a regressed sql after upgrade to 11g from 10g. The problem sql looks like:

SELECT 
       fc.gjmfmpbe_type, 
       fc.gjmfmpbe_config_seq, 
       fi.gjmfmpbe_info_seq, 
       fd.gjmfmpbe_detail_seq, 
       fi.physical_gjmf_date, 
       fi.gjmf_name, 
       fi.mpbe_timestamp, 
       fd.gjmf_detail, 
       fc.mog_prefix, 
       fd.gjmf_detail_enc, 
       fds.retry_count, 
       fc.retry_config 
FROM   
       gjmfmpbe_config fc, 
       gjmfmpbe_detail_status fds,
       gjmfmpbe_detail fd, 
       gjmfmpbe_info fi 
WHERE  ( fi.gjmfmpbe_info_seq = fd.gjmfmpbe_info_seq ) 
       AND ( fds.gjmfmpbe_detail_seq = fd.gjmfmpbe_detail_seq ) 
       AND ( fi.gjmfmpbe_config_seq = fc.gjmfmpbe_config_seq ) 
       AND ( fds.status IN ( 'LD', 'RT' ) ) 
       AND ( fc.gjmf_directory = 'BillCycle' ) 
       AND ( fds.thread_id = '1' ) 
ORDER  BY fd.gjmfmpbe_detail_seq;  

The execution plans of this sql in 10g and 11g are shown below, respectively:

10 g execution plan
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name                       | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                            |       |       |  1477 (100)|          |
|   1 |  SORT ORDER BY                    |                            |    13 |  4641 |  1477   (1)| 00:00:18 |
|   2 |   NESTED LOOPS                    |                            |    13 |  4641 |  1476   (1)| 00:00:18 |
|   3 |    NESTED LOOPS                   |                            |   486 |   116K|   990   (1)| 00:00:12 |
|   4 |     MERGE JOIN CARTESIAN          |                            |   486 | 25758 |    17   (0)| 00:00:01 |
|   5 |      TABLE ACCESS BY INDEX ROWID  | GJMFMPBE_CONFIG            |     1 |    34 |     2   (0)| 00:00:01 |
|   6 |       INDEX RANGE SCAN            | GJMFMPBE_CONFIG_FILEDIR    |     1 |       |     1   (0)| 00:00:01 |
|   7 |      BUFFER SORT                  |                            |   486 |  9234 |    15   (0)| 00:00:01 |
|   8 |       INLIST ITERATOR             |                            |       |       |            |          |
|   9 |        TABLE ACCESS BY INDEX ROWID| GJMFMPBE_DETAIL_STATUS     |   486 |  9234 |    15   (0)| 00:00:01 |
|  10 |         INDEX RANGE SCAN          | GJMFMPBE_DETAIL_STATUS_IX1 |   486 |       |     6   (0)| 00:00:01 |
|  11 |     TABLE ACCESS BY INDEX ROWID   | GJMFMPBE_DETAIL            |     1 |   193 |     2   (0)| 00:00:01 |
|  12 |      INDEX UNIQUE SCAN            | PK_GJMFMPBE_DETAIL         |     1 |       |     1   (0)| 00:00:01 |
|  13 |    TABLE ACCESS BY INDEX ROWID    | GJMFMPBE_INFO              |     1 |   111 |     1   (0)| 00:00:01 |
|  14 |     INDEX UNIQUE SCAN             | PK_GJMFMPBE_INFO           |     1 |       |     0   (0)|          |
----------------------------------------------------------------------------------------------------------------


11 g execution plan 

---------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name                       | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |                            |       |       | 11130 (100)|       |
|   1 |  SORT ORDER BY                   |                            |   108 | 37692 | 11130   (1)| 00:02:14 |
|*  2 |   HASH JOIN                      |                            |   108 | 37692 | 11129   (1)| 00:02:14 |
|   3 |    TABLE ACCESS BY INDEX ROWID   | GJMFMPBE_CONFIG            |     1 |    25 |     2   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN             | GJMFMPBE_CONFIG_FILEDIR    |     1 |       |     1   (0)| 00:00:01 |
|*  5 |    HASH JOIN                     |                            |  4333 |  1370K| 11127   (1)| 00:02:14 |
|   6 |     NESTED LOOPS                 |                            |       |       |            |       |
|   7 |      NESTED LOOPS                |                            |  4333 |   901K|  8733   (1)| 00:01:45 |
|   8 |       TABLE ACCESS BY INDEX ROWID| GJMFMPBE_DETAIL_STATUS     |  4333 | 77994 |    59   (0)| 00:00:01 |
|*  9 |        INDEX RANGE SCAN          | GJMFMPBE_DETAIL_STATUS_IX1 |  2183 |       |    18   (0)| 00:00:01 |
|* 10 |       INDEX UNIQUE SCAN          | PK_GJMFMPBE_DETAIL         |     1 |       |     1   (0)| 00:00:01 |
|  11 |      TABLE ACCESS BY INDEX ROWID | GJMFMPBE_DETAIL            |     1 |   195 |     2   (0)| 00:00:01 |
|  12 |     TABLE ACCESS FULL            | GJMFMPBE_INFO              |   466K|    49M|  2388   (1)| 00:00:29 |
---------------------------------------------------------------------------------------------------------------

The difference lies in the join order. In 10g join order: fc -> fds -> fd -> fi, and in 11g join order: fc -> (fds -> fd -> fi). In 11g the buffer gets per execution is around 427K as shown with below query:

select sql_id, child_number, buffer_gets/executions, executions, sql_plan_baseline from v$sql where sql_id='cz1myj2gx5xwv';

SQL_ID        CHILD_NUMBER BUFFER_GETS/EXECUTIONS EXECUTIONS SQL_PLAN_BASELINE
------------- ------------ ---------------------- ---------- ------------------------------
cz1myj2gx5xwv            0             427447.751        233

Before upgrade, we backed up 10g execution plan in a sql tuning set. so I was able to obtain the buffer gets per execution in 10g by:

SELECT sql_id, plan_hash_value, executions, buffer_gets/executions from
   table(dbms_sqltune.select_sqlset(
       'SPM_STS'
      ,'sql_id=''cz1myj2gx5xwv'''
      , SQLSET_OWNER=>'OPS$ORACLE'
 )
   );  
  


SQL_ID        PLAN_HASH_VALUE EXECUTIONS BUFFER_GETS/EXECUTIONS
------------- --------------- ---------- ----------------------
cz1myj2gx5xwv      1052698328       2742             31115.0627

Now come to the fix. I executed the following procedure to load the 10 plan stored in a SQL tuning set (STS) into SQL plan baselines for this problem sql

DECLARE
  l_plans_loaded  PLS_INTEGER;
BEGIN
  l_plans_loaded := DBMS_SPM.load_plans_from_sqlset(
    SQLSET_NAME => 'SPM_STS'
   ,SQLSET_OWNER => 'OPS$ORACLE'
   ,BASIC_FILTER =>  'sql_id=''cz1myj2gx5xwv'''
 );
END;
/

To verify the problem is fixed, I checked the execution stats shortly after:

select sql_id, child_number, buffer_gets/executions,round(elapsed_time/1000000/executions) ela_secs_exe, executions, sql_plan_baseline from v$sql where sql_id='cz1myj2gx5xwv';

SQL_ID        CHILD_NUMBER BUFFER_GETS/EXECUTIONS ELA_SECS_EXE EXECUTIONS SQL_PLAN_BASELINE
------------- ------------ ---------------------- ------------ ---------- ------------------------------
cz1myj2gx5xwv            0              433577.21         2414        233
cz1myj2gx5xwv            2                  11936            4         14 SQL_PLAN_4090fd80m1dzb80df0a95

WOW! 2414 seconds vs 4 seconds ??? So why the 11g chose the bad execution plan in the first place? I will investigate further if possible.


 ----------------- update Jul. 10, 2012 -----------------

The difference between 11g and 10g plan is not about join order. It is that in 11g Oracle CBO accepted "inlist as filter" access path. I did 10053 trace for the following sql:

select * from  ttq_bbbb.gjmfmpbc_detail_status fds where fds.thread_id= '1' and fds.status in ('LD', 'RT');

The execution plan looks like:

----------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name                       | Rows  | Bytes | Cost (%CPU)| Time  |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                            |  4332 |   135K|    59   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| GJMFMPBC_DETAIL_STATUS     |  4332 |   135K|    59   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | GJMFMPBC_DETAIL_STATUS_IX1 |  2167 |       |    18   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("FDS"."THREAD_ID"='1')
       filter("FDS"."STATUS"='LD' OR "FDS"."STATUS"='RT')

Note: the index GJMFMPBC_DETAIL_STATUS_IX1 is on GJMFMPBC_DETAIL_STATUS ( thread_id, status). In the trace, it can be seen:

Access Path: index (RangeScan)
    Index: GJMFMPBC_DETAIL_STATUS_IX1
    resc_io: 115.00  resc_cpu: 2790630
    ix_sel: 0.000043  ix_sel_with_filters: 0.000043
    Cost: 115.30  Resp: 115.30  Degree: 1
  Considering index with inlist as filter
 
  ColGroup Usage:: PredCnt: 2  Matches Full: #1  Partial:  Sel: 0.0000
  Access Path: index (RangeScan)
    Index: GJMFMPBC_DETAIL_STATUS_IX1
    resc_io: 59.00  resc_cpu: 2439947
    ix_sel: 0.000021  ix_sel_with_filters: 0.000021
 ***** Logdef predicate Adjustment ******
 Final IO cst 0.00 , CPU cst 0.00
 ***** End Logdef Adjustment ******
    Cost: 59.26  Resp: 59.26  Degree: 1
  Accepted inlist as filter
  ****** trying bitmap/domain indexes ******
  ****** finished trying bitmap/domain indexes ******
  Best:: AccessPath: IndexRange
  Index: GJMFMPBC_DETAIL_STATUS_IX1
         Cost: 59.26  Degree: 1  Resp: 59.26  Card: 4331.78  Bytes: 0

Composite index selectivity

I did tests with 10053 trace today and found that Oracle CBO behavior changes regarding compute selectivity of 3-column composite index from 9.2.0.8 to 10.2.0.4. (note: no histogram on any columns)

In 9i: selectivty of index(col1, col2, col3)= density (co11) x denisty (col2) x denisity(col3);

In 10g and 11g selectivity of index(col1, col2, col3) = 1/DISTINCT_KEYS where DISTINCT_KEYS is from index stats obtainable through dba_indexes.


Here is the test case which mimics the production able and the problem sql.

----- begin of the test case ----

drop table test;
create table test
as
select level id,
       trunc(mod(level,80)) id1,
       20*trunc(mod(level, 40)) id2,
       1    id3,
       trunc(mod(level,50)) id4
from dual
connect by level <=1000000;


create index test_ix1 on test(id1, id2, id3);

exec dbms_stats.gather_table_stats(user,'test', method_opt=>'FOR ALL COLUMNS size 1', cascade=>true);


alter session set tracefile_identifier = test;
ALTER SESSION SET EVENTS='10053 trace name context forever, level 1';

explain plan for
select id
from test
where id1 = 20
and id3=1
and id2 = 400;

ALTER SESSION SET EVENTS '10053 trace name context off';
Exit
------ end of test case  -----------------------

#### 9.2.0.8  10053 trace excerpt


***************************************
SINGLE TABLE ACCESS PATH
Column:        ID1  Col#: 2      Table: TEST   Alias: TEST
    NDV: 80        NULLS: 0         DENS: 1.2500e-02 LO:  0  HI: 79
    NO HISTOGRAM: #BKT: 1 #VAL: 2
Column:        ID3  Col#: 4      Table: TEST   Alias: TEST
    NDV: 1         NULLS: 0         DENS: 1.0000e+00 LO:  1  HI: 1
    NO HISTOGRAM: #BKT: 1 #VAL: 2
Column:        ID2  Col#: 3      Table: TEST   Alias: TEST
    NDV: 40        NULLS: 0         DENS: 2.5000e-02 LO:  0  HI: 780
    NO HISTOGRAM: #BKT: 1 #VAL: 2
  TABLE: TEST     ORIG CDN: 1000000  ROUNDED CDN: 313  CMPTD CDN: 313
  Access path: tsc  Resc:  857  Resp:  847
  Access path: index (equal)
      Index: TEST_IX1
  TABLE: TEST
      RSC_CPU: 711380   RSC_IO: 82
  IX_SEL:  0.0000e+00  TB_SEL:  3.1250e-04
  BEST_CST: 83.00  PATH: 4  Degree:  1


#### 10.2.0.4  10053 trace excerpt

***************************************
SINGLE TABLE ACCESS PATH
  -----------------------------------------
  BEGIN Single Table Cardinality Estimation
  -----------------------------------------
  Column (#2): ID1(NUMBER)
    AvgLen: 3.00 NDV: 81 Nulls: 0 Density: 0.012346 Min: 0 Max: 79
  Column (#4): ID3(NUMBER)
    AvgLen: 3.00 NDV: 1 Nulls: 0 Density: 1 Min: 1 Max: 1
  Column (#3): ID2(NUMBER)
    AvgLen: 4.00 NDV: 40 Nulls: 0 Density: 0.025 Min: 0 Max: 780
  Table: TEST  Alias: TEST
    Card: Original: 1003092  Rounded: 310  Computed: 309.60  Non Adjusted: 309.60
  -----------------------------------------
  END   Single Table Cardinality Estimation
  -----------------------------------------
  Access Path: TableScan
    Cost:  730.88  Resp: 730.88  Degree: 0
      Cost_io: 700.00  Cost_cpu: 284170229
      Resp_io: 700.00  Resp_cpu: 284170229
  Access Path: index (AllEqRange)
    Index: TEST_IX1
    resc_io: 3173.00  resc_cpu: 27721329
    ix_sel: 0.0125  ix_sel_with_filters: 0.0125
    Cost: 3176.01  Resp: 3176.01  Degree: 1
  Best:: AccessPath: TableScan
         Cost: 730.88  Degree: 1  Resp: 730.88  Card: 309.60  Bytes: 0

Note:
select index_name, distinct_keys from user_indexes where index_name='TEST_IX1';

INDEX_NAME                     DISTINCT_KEYS
------------------------------ -------------
TEST_IX1                                  80


#### 11.2.0.1  10053 trace excerpt


***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for TEST[TEST]
  ColGroup (#1, Index) TEST_IX1
    Col#: 2 3 4    CorStregth: 40.00
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  Table: TEST  Alias: TEST
    Card: Original: 1000000.000000  Rounded: 12500  Computed: 12500.00  Non Adjusted: 12500.00
  Access Path: TableScan
    Cost:  629.80  Resp: 629.80  Degree: 0
      Cost_io: 617.00  Cost_cpu: 283372261
      Resp_io: 617.00  Resp_cpu: 283372261
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  ColGroup Usage:: PredCnt: 3  Matches Full: #1  Partial:  Sel: 0.0125
  Access Path: index (AllEqRange)
    Index: TEST_IX1
    resc_io: 3173.00  resc_cpu: 27721329
    ix_sel: 0.012500  ix_sel_with_filters: 0.012500
    Cost: 3174.25  Resp: 3174.25  Degree: 1
  Best:: AccessPath: TableScan
         Cost: 629.80  Degree: 1  Resp: 629.80  Card: 12500.00  Bytes: 0

Notice the ix_sel line in the above 10053 trace excerpt; for 10g and 11g it equal to 1/80. for 9i seems computed through multiplying selectivity of eeach column.

Update:
Came accross Jonathan Lewis's comment, and came to know this CBO behavior changes acctually from 10.1.0.4 ie. 10.1.0.4 is still similar to 9i behavior.


Below is his comment: (http://kr.forums.oracle.com/forums/thread.jspa?messageID=3153224)

--------
For a single-table query with the predicate
(full list of index columns) = (set of values)

The selectivities vary across version as follows:

11.1.0.6: Table selectivity and index selectivity given by distinct_keys in index
10.2.0.1: Table selectivity given by product of column selectivities, index selectivity given by distinct_keys in index
10.1.0.4: Table selectivity and index selectivity given by product of column selectivities

------------

JL's original post about this behavior: http://jonathanlewis.wordpress.com/2008/03/11/everything-changes/

LIKE does not like bind variable

Today, I have learned this in a hard way. After the release, a query was time-out frequently. I have spent quite a lot of time to figure out what's going on. When checking the execution plan from the memory, there were always two plans, one good with nested loop join and one bad with hash join. Trying to add hint to force nested loop join, however, it did not work.

The problem is that the query has a predicate such as A.ORDER_ID LIKE 'ICN000104775%', but it is fired from application server and is using bind variable.

When checking why there were different versions of execution plan, I found out the following from the v$sql_shared_cursor in one occasion.

ADDRESS          KGLHDPAR         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 L
---------------- ---------------- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
000000054EF09208 0000000516791558 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
0000000532A02020 0000000516791558 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
00000005327D3808 0000000516791558 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

The forth field from the right is called USER_BIND_PEEK_MISMATCH

The following test demonstrated that LIKE operator is not getting along with bind variable:

1. In the case of literal, execution plan looks perfect

SQL> SELECT
2     a.ACCOUNT_ID
3       ,a.IO_ID
4       ,a.ORDER_ID
5       ,a.IS_MASTER
6       ,a.IS_PQ
7     FROM
8        TAB_A a,
9        TAB_B b
10     WHERE
11        a.ORDER_ID LIKE  'ISPT143730263%'
12     AND a.io_id = b.io_id
13     AND (a.IS_VALID='Y' OR (a.IS_VALID='N' AND b.ORDER_STATUS_ID=6));


Execution Plan
----------------------------------------------------------
0      SELECT STATEMENT Optimizer=CHOOSE (Cost=7 Card=1 Bytes=45)
1    0   TABLE ACCESS (BY INDEX ROWID) OF 'TAB_B' (Cost=3 Card=1 Bytes=10)
2    1     NESTED LOOPS (Cost=7 Card=1 Bytes=45)
3    2       TABLE ACCESS (BY INDEX ROWID) OF 'TAB_A' (Cost=4 Card=1 Bytes=35)
4    3         INDEX (RANGE SCAN) OF 'TAB_A_IX5' (UNIQUE) (Cost=3 Card=1)
5    2       INDEX (RANGE SCAN) OF 'TAB_B_IX1' (NON-UNIQUE) (Cost=2 Card=1)

2. In the case of bind variable, totally wrong cardinality:

SQL>
SQL>
SQL> @s1
SQL> variable v varchar2(16);
SQL> exec :v :='ISPT143730263%';

PL/SQL procedure successfully completed.

SQL>
SQL> SELECT
2     a.ACCOUNT_ID
3       ,a.IO_ID
4       ,a.ORDER_ID
5       ,a.IS_MASTER
6       ,a.IS_PQ
7     FROM
8        TAB_A a,
9        TAB_B b
10     WHERE
11        a.ORDER_ID LIKE  :v
12       AND a.io_id = b.io_id
13       AND (a.IS_VALID='Y' OR (a.IS_VALID='N' AND b.ORDER_STATUS_ID=6));


Execution Plan
----------------------------------------------------------
0      SELECT STATEMENT Optimizer=CHOOSE (Cost=227422 Card=833902 Bytes=37525590)
1    0   HASH JOIN (Cost=227422 Card=833902 Bytes=37525590)
2    1     TABLE ACCESS (BY INDEX ROWID) OF 'TAB_A' (Cost=45900 Card=1516186 Bytes=53066510)
3    2       INDEX (RANGE SCAN) OF 'TAB_A_IX5' (UNIQUE) (Cost=1064 Card=272913)
4    1     TABLE ACCESS (FULL) OF 'TAB_B' (Cost=170305 Card=30317333 Bytes=303173330)

We have a function index based on substr(order_id, 1, 13), so the fix is to use substr(order_id, 1,13)=:v as the predicate.

Ed. Sep 23, 2009 -

I come accross a paper "A LOOK UNDER THE HOOD OF CBO: THE 10053 EVENT " by Wolfgang Breitling . I have learned the filter factor (selectivity) of LIKE operator is as follows:

predicate               filter factor
-------------           -------------
c1 like  value          c1.density
c1 like :b1             0.05 OR c1.density

In the case of like with bind variable, the filter factor depends on the hidden parameter _LIKE_WITH_BIND_AS_EQUALITY. When it is false (the default), 0.05 is chosen, otherwise c1.density. This is why I saw unrealistic high cardinality in my case above.

Update: Feb 20, 2011

Today, caught by same issue again in the same database (only now we are in 10g not 9i) . Last night during code release, a query was changed:

--------------
before release
--------------

SELECT 
a.PSEFS_ID
, b.PSEFS_STATUS_ID
, TO_CHAR(b.PSEFS_CRFBTF_DATE, 'MM/DD/YYYY HH24:MI:SS') AS "PSEFS_CRFBTF_DATE"
, b.PRESALE_ACTIVITY_ID
, b.PSEFS_TYPE_ID
, b.PSEFS_SUB_TYPE_ID
, b.WORKWITH
, b.WORKWITH_GROUP_ID 
FROM PSEFS_MBSTFR a
   , PSEFS_DFTBJLS b 
WHERE substr(a.PSEFS_ID,1,13) = substr(:b,1,13) 
AND a.INT_SUPP_PSEFS_ID = 0 
AND a.INT_PSEFS_ID = b.INT_PSEFS_ID;

---------------
After release
--------------

SELECT 
  a.PSEFS_ID
, b.PSEFS_STATUS_ID
, TO_CHAR(b.PSEFS_CRFBTF_DATE, 'MM/DD/YYYY HH24:MI:SS') AS "PSEFS_CRFBTF_DATE"
, b.PRESALE_ACTIVITY_ID
, b.PSEFS_TYPE_ID
, b.PSEFS_SUB_TYPE_ID
, b.WORKWITH
, b.WORKWITH_GROUP_ID  
FROM PSEFS_MBSTFR a
   , PSEFS_DFTBJLS b  
WHERE a.PSEFS_ID like substr(:b,1,13)||'%' 
 AND a.INT_SUPP_PSEFS_ID = 0
 AND a.INT_PSEFS_ID = b.INT_PSEFS_ID
 ORDER BY a.INT_BASE_PSEFS_ID,a.IS_PQ;

So the predicate changed from : substr(a.PSEFS_ID,1,13) = substr(:b,1,13) to: a.PSEFS_ID like substr(:b,1,13)||'%'    Guess what? Now the new query uses hash join and time-out. The 0.05 filter factor makes CBO think from the predicate (a.PSEFS_ID like substr(:b,1,13)||'%' ) there will come out 580K rows, thus hash join is the best choice :-(. Fortunately, we are in 10g now, so I have the choice to use sql profile to freeze the good plan without the code change. But the predicate change in this case makes no sense, having asked the dev team to revert back in the next available maintainence window.

Some notes about tuning a sql

From my limited experience, the following methods are used or can be used to tune a sql

1. Obtain optimizer execution plan by autotrace and check consistent gets from the autotrace.

2. Obtain real run-time execution plan:
- Fire the sql
- Obtain the hash value, address or sql_id (in 10g) of the sql from v$sql
- Generate the execution plan from v$sql_plan
- Kill the session

3. Judge if the exection plan is reasonable,
- check all the indexes of tables involved
- check table column stats if needed
- check table stats if needed
- check v$session_longops to see the time estimation for available operations.
- join order, join type

4. 10046 event trace/TKPROF

5. 10053 event trace

6. Oracle SQLT tool

7. OEM SQL tunning advisor

8. SQL Profile

Burleson has a page that provides overview of SQL tuning: Oracle tuning - Tune individual SQL statements