We had complaint about a batch job that took much longer to complete on environment A then on environment B.

I checked and indeed the plans where different

As we recently updated from 11.2.0.4 BP12 to BP15 on that environment (A) my first idea was that this caused the issue,  to exclude everything I imported the table stats from the working environment B to the environment A.
Still I got the same plan.

I checked the system stats they were the same.
I used Mauro Pagano’s excellent SQLd360 tool get it here and couldn’t see anything (that’s ENTIRELY my fault I could really work on this and was multitasking a lot due to other constraints;-).

I ran a 10053 optimizer trace and saw that there were fix controls not used on env B and only FTS were used in SINGLE TABLE ACCESS PATH , …. bizar 
Environment A

SINGLE TABLE ACCESS PATH 
  Single Table Cardinality Estimation for TABLE_X[TABLE_X] 
  Column (#2): 
    NewDensity:0.000210, OldDensity:0.000476 BktCnt:254, PopBktCnt:2, PopValCnt:1, NDV:4725
  Column (#2): COL2(
    AvgLen: 7 NDV: 4725 Nulls: 0 Density: 0.000210 Min: 113898 Max: 814396873
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 254
  Column (#3): 
    NewDensity:0.000019, OldDensity:0.001339 BktCnt:254, PopBktCnt:18, PopValCnt:9, NDV:48180
  Column (#3): COL3(
    AvgLen: 7 NDV: 48180 Nulls: 0 Density: 0.000019 Min: 113328 Max: 816880773
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 246

  Table: TABLE_X  Alias: TABLE_X
    Card: Original: 633107.000000  Rounded: 1  Computed: 0.00  Non Adjusted: 0.00
  Access Path: TableScan
    Cost:  1113.98  Resp: 1113.98  Degree: 0
      Cost_io: 1100.00  Cost_cpu: 180830851
      Resp_io: 1100.00  Resp_cpu: 180830851
  Best:: AccessPath: TableScan
         Cost: 1113.98  Degree: 1  Resp: 1113.98  Card: 0.00  Bytes: 0

While on the other env B

SINGLE TABLE ACCESS PATH 
  Single Table Cardinality Estimation for TABLE_X[TABLE_X] 
  Column (#2): 
    NewDensity:0.000210, OldDensity:0.000476 BktCnt:254, PopBktCnt:2, PopValCnt:1, NDV:4725
  Column (#2): COL2(
    AvgLen: 7 NDV: 4725 Nulls: 0 Density: 0.000210 Min: 113898 Max: 814396873
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 254
  Column (#3): 
    NewDensity:0.000019, OldDensity:0.001339 BktCnt:254, PopBktCnt:18, PopValCnt:9, NDV:48180
  Column (#3): COL3(
    AvgLen: 7 NDV: 48180 Nulls: 0 Density: 0.000019 Min: 113328 Max: 816880773
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 246
  ColGroup (#1, Index) IX_4
    Col#: 4 5    CorStregth: -1.00
  ColGroup Usage:: PredCnt: 2  Matches Full:  Partial: 
  Table: TABLE_X  Alias: TABLE_X
    Card: Original: 633107.000000  Rounded: 1  Computed: 0.00  Non Adjusted: 0.00
  Access Path: TableScan
    Cost:  1113.55  Resp: 1113.55  Degree: 0
      Cost_io: 1100.00  Cost_cpu: 180830851
      Resp_io: 1100.00  Resp_cpu: 180830851
  Access Path: index (AllEqRange)
    Index: IX_2
    resc_io: 9.00  resc_cpu: 69774
    ix_sel: 0.000019  ix_sel_with_filters: 0.000019 
    Cost: 9.01  Resp: 9.01  Degree: 1
  Access Path: index (AllEqRange)
    Index: IX_3
    resc_io: 28.00  resc_cpu: 257919
    ix_sel: 0.000210  ix_sel_with_filters: 0.000210 
    Cost: 28.02  Resp: 28.02  Degree: 1
  ****** trying bitmap/domain indexes ******
  Access Path: index (AllEqRange)
    Index: IX_2
    resc_io: 3.00  resc_cpu: 23964
    ix_sel: 0.000019  ix_sel_with_filters: 0.000019 
    Cost: 3.00  Resp: 3.00  Degree: 0
  Access Path: index (AllEqRange)
    Index: IX_3
    resc_io: 3.00  resc_cpu: 47964
    ix_sel: 0.000210  ix_sel_with_filters: 0.000210 
    Cost: 3.00  Resp: 3.00  Degree: 0
  Bitmap nodes:
    Used IX_2
      Cost = 3.001919, sel = 0.000019
    Used IX_3j
      Cost = 3.004938, sel = 0.000210
  Access path: Bitmap index – accepted
    Cost: 6.007407 Cost_io: 6.000536 Cost_cpu: 91721.496173 Sel: 0.000000
    Not Believed to be index-only
  ****** finished trying bitmap/domain indexes ******
******** Begin index join costing ********
  Access Path: index (FullScan)
    Index: IX_1
    resc_io: 1439.00  resc_cpu: 136869152
    ix_sel: 1.000000  ix_sel_with_filters: 1.000000 
    Cost: 1449.25  Resp: 1449.25  Degree: 0

Being in a hurry because I was busy with plenty of stuff  I assumed  that fix_control was the problem
however setting fix_control didn’t change a thing so I went back to check  the trace with a colleague  and then we saw following

Table Stats::
  Table: TABLE_X  Alias: TABLE_X
    #Rows: 633107  #Blks:  4056  AvgRowLen:  43.00  ChainCnt:  0.00
Index Stats::
  Index: IX_1  Col#: 1
    LVLS: 2  #LB: 1437  #DK: 633107  LB/K: 1.00  DB/K: 1.00  CLUF: 37633.00
  Index: IX_2  Col#: 3
    LVLS: 2  #LB: 1665  #DK: 48180  LB/K: 1.00  DB/K: 5.00  CLUF: 287723.00
    INVISIBLE
  Index: IX_3  Col#: 2
    LVLS: 2  #LB: 2103  #DK: 4725  LB/K: 1.00  DB/K: 25.00  CLUF: 118278.00
    INVISIBLE
  Index: IX_4  Col#: 4 5
    LVLS: 2  #LB: 2490  #DK: 14906  LB/K: 1.00  DB/K: 2.00  CLUF: 36217.00
    INVISIBLE

We checked the status of the indexes they were INVISIBLE, when they were put back to VISIBLE the correct plan was choosen again …

Moral of the story : As one of my previous managers (probably the best I had so far but that is another story )said Assumption is the mother of all f*ck ups, don’t think that everything is a complicated problem and check basic things, and take your time to check things don’t do 50 things at the same time, man anyway can’t multitask ;————-)
luckily in the end it didn’t take to much time to identify the issue…

Thanks @MartinDBA, @Mautro and everyone interacting in the discussion on twitter

On By phil

Leave a Reply

Related Post