Monday, July 23, 2012

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)

5 comments:

jdevp2 said...

Hi Denis,

Thanks for the clear explanation. Can you explain how to fool CBO through setting column stats manually so that you were able to get the 10g access path with much better gets per execution in this case ?

jdevp2 said...
This comment has been removed by a blog administrator.
yds said...

@jdevp2 - in dbms_stats package there are procedures you can use to set column,index stats manaually

for example:
PROCEDURE SET_INDEX_STATS
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
OWNNAME VARCHAR2 IN
INDNAME VARCHAR2 IN
PARTNAME VARCHAR2 IN DEFAULT
STATTAB VARCHAR2 IN DEFAULT
STATID VARCHAR2 IN DEFAULT
NUMROWS NUMBER IN DEFAULT
NUMLBLKS NUMBER IN DEFAULT
NUMDIST NUMBER IN DEFAULT
AVGLBLK

...
In this case, in 11g, you can use above procedure to set NUMDIST of an index to a very large value, so the index selectivity could be close to 10g. This is just a possible way, but may be not the good way. In 11g, generally we may want to collect stats using 11g default behavior, most likly we can get good execution plan without "fool" CBO.

jdevp2 said...

Thanks for the response. I'm not sure if we encounter the same issue. After 11g upgrade, it seems that our SAP report is running very slow based on the following query. Unfortunately, we did not save the baseline under 10g so we can't compare the query plans.

SELECT
"OBJEK"
FROM
"AUSP"
WHERE
"MANDT" = :A0 AND "OBJEK" IN ( :A1 , :A2 , :A3 , :A4 , :A5 ) AND "MAFID" = :A6 AND "KLART" = :A7
AND "ATINN" = :A8 AND "ATWRT" = :A9 AND "DATUV" <= :A10

SELECT STATEMENT ( Estimated Costs = 2 , Estimated #Rows = 0 )

2 INLIST ITERATOR

1 INDEX RANGE SCAN AUSP~N3
( Estim. Costs = 2 , Estim. #Rows = 1 )
Search Columns: 7
Estim. CPU-Costs = 28,526 Estim. IO-Costs = 2
Access Predicates


NONUNIQUE Index AUSP~N3

Column Name #Distinct

MANDT 1
OBJEK 1,131,208
KLART 6
ATINN 571
ATWRT 45,269
MAFID 1
DATUV 1
Looks like that it does pick up the correct index. I set the optimizer_feature_enable back to 10g at session level and run autotrace but didn't see any plan changes. I also did histogram on all the columns with no result so I can't be certain if the INLIST is the problem.

yds said...

Can you show the execution plan of this sql using dbms_xplan,display_cursor ? Sometimes AUTOTRACE show you the execution plan is different from what really is from the cursor.