ANBOB™

最近有个银行客户咨询，他们一个系统有个SQL在凌晨1点左右执行计划突然变差了，数据库为oracle 11.2.0.4 RAC， 从AWR看数据库该时段实例级几乎空闲，上线很久的业务，问题时间点无人为操作，SQL特征是查询一个分区表，2个列上查询条件，并不包含分区键列， 其中有一个列使用了绑定变量，执行计划有原来使用绑定变量列的索引改为全表分区扫描，直到白天10点以后人为收集了统计信息恢复正常。 简单记录如下

AWR 问题时间点负载

SQL执行计划历史

从SQLHC中可以获取以下信息

Historical SQL Statistics – Delta (DBA_HIST_SQLSTAT)

Performance metrics of Execution Plans of 4ruhsafdgfj0x.
This section includes data captured by AWR. If this is a stand-by read-only database then the AWR information below is from the Primary database.

Note:

从以上可以确认是在2023-05-06/01:30前从实例2开始执行的SQL执行计划发生改变，逻辑读和响应时间翻了近10倍。平时SQL的执行次数并不多，so，你懂得

查看两个执行计划

Inst: 2   Child: 0    Plan hash value: 1429561684

                      --------------------------------------------------------------------------------------------------------------------------
                      | Id  | Operation                           | Name              | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | Pstart| Pstop |
                      --------------------------------------------------------------------------------------------------------------------------
                      |   0 | SELECT STATEMENT                    |                   |        |       |  1058 (100)|          |       |       |
                      |   1 |  SORT AGGREGATE                     |                   |      1 |    27 |            |          |       |       |
                      |*  2 |   TABLE ACCESS BY GLOBAL INDEX ROWID| TAB_QWERTYUIOPAS  |    112 |  3024 |  1058   (0)| 00:00:13 | ROWID | ROWID |
                      |*  3 |    INDEX RANGE SCAN                 | INX_EXTXXX3       |   3634 |       |    19   (0)| 00:00:01 |       |       |
                      --------------------------------------------------------------------------------------------------------------------------
                      Query Block Name / Object Alias (identified by operation id):
                      -------------------------------------------------------------
                         1 - SEL$F5BB74E1
                         2 - SEL$F5BB74E1 / O@SEL$2
                         3 - SEL$F5BB74E1 / O@SEL$2
                      Outline Data
                      -------------
                        /*+
                            BEGIN_OUTLINE_DATA
                            IGNORE_OPTIM_EMBEDDED_HINTS
                            OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
                            DB_VERSION('11.2.0.4')
                            OPT_PARAM('_b_tree_bitmap_plans' 'false')
                            OPT_PARAM('_bloom_filter_enabled' 'false')
                            OPT_PARAM('_optimizer_extended_cursor_sharing' 'none')
                            OPT_PARAM('_optimizer_extended_cursor_sharing_rel' 'none')
                            OPT_PARAM('_optimizer_adaptive_cursor_sharing' 'false')
                            OPT_PARAM('_optimizer_use_feedback' 'false')
                            ALL_ROWS
                            OUTLINE_LEAF(@"SEL$F5BB74E1")
                            MERGE(@"SEL$2")
                            OUTLINE(@"SEL$1")
                            OUTLINE(@"SEL$2")
                            INDEX_RS_ASC(@"SEL$F5BB74E1" "O"@"SEL$2" ("TAB_QWERTYUIOPAS"."EXTEND3"))
                            END_OUTLINE_DATA
                        */
                      Peeked Binds (identified by position):
                      --------------------------------------
                         1 - (VARCHAR2(30), CSID=852): '221125'
                    Predicate Information (identified by operation id):
                      ---------------------------------------------------
                         2 - filter(("O"."QUERYxxxx">='2023/03/01 00:00:00' AND "O"."QUERYxxxx"<='2023/03/31 00:00:00'))
                         3 - access("O"."Exxxx3"=:1)

Plan hash value: 1634677993

----------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name              | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                   |       |       |   740K(100)|          |       |       |
|   1 |  SORT AGGREGATE      |                   |     1 |    27 |            |          |       |       |
|   2 |   PARTITION RANGE ALL|                   | 86226 |  2273K|   740K  (1)| 02:28:08 |     1 |     6 |
|   3 |    TABLE ACCESS FULL | TAB_QWERTYUIOPAS  | 86226 |  2273K|   740K  (1)| 02:28:08 |     1 |     6 |
----------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$F5BB74E1
   3 - SEL$F5BB74E1 / O@SEL$2
Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
      DB_VERSION('11.2.0.4')
      OPT_PARAM('_b_tree_bitmap_plans' 'false')
      OPT_PARAM('_bloom_filter_enabled' 'false')
      OPT_PARAM('_optimizer_extended_cursor_sharing' 'none')
      OPT_PARAM('_optimizer_extended_cursor_sharing_rel' 'none')
      OPT_PARAM('_optimizer_adaptive_cursor_sharing' 'false')
      OPT_PARAM('_optimizer_use_feedback' 'false')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$F5BB74E1")
      MERGE(@"SEL$2")
      OUTLINE(@"SEL$1")
      OUTLINE(@"SEL$2")
      FULL(@"SEL$F5BB74E1" "O"@"SEL$2")
      END_OUTLINE_DATA
  */
Peeked Binds (identified by position):
--------------------------------------

   1 - :1 (VARCHAR2(30), CSID=852): '001358'

NOTE:
从上面我们可以看到确实有两个执行计划，同时当前是禁用了SQL ACS，但bind peek功能启用，记录下两个变量值及对应的两个执行计划。

通常首先需要排除问题时间是否表有DDL,或统计信息改变，因为无人为操作且从last_ddl_time可以排除，下面看统计信息历史。

统计信息历史版本

Tables Statistics Versions

Indexes Statistics Versions: TAB_QWERTYUIOPAS (USR)

NOTE:

注意表和索引该时间段都没有自动收集。  因为上面有绑定变量窥探到的变量值，那我们把全表扫时的变量带进去，确认真的是收集统计信息修正了吗？

10053 TRACE

当我们带入001358变量值后，还可以复现全表扫描，那到这里可能有人想到了问题点。下面直接附上10053 trace file部分内容。

SQL> connect / as sysdba
SQL> oradebug setmypid
SQL> oradebug unlimit
SQL> oradebug event 10053 trace name context forever, level 1

SQL> explain plan for  ...enter your query here...

SQL> oradebug event 10053 trace name context off
SQL> oradebug tracefile_name

-- trace file
*******************************************
Peeked values of the binds in SQL statement
*******************************************

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT COUNT(*) "TOTAL_COUNT" FROM "USR"."TAB_QWERTYUIOPAS" "O" WHERE "O"."QUERYXXX">='2023/03/01 00:00:00' 
AND "O"."QUERYXXX"<='2023/03/31 00:00:00' AND "O"."EXXXX3"='001358' AND '2023/03/31 00:00:00'>='2023/03/01 00:00:00'
kkoqbc: optimizing query block SEL$F5BB74E1 (#0)

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: TAB_QWERTYUIOPAS  Alias:  O  (Using composite stats)
    #Rows: 58992346  #Blks:  2734209  AvgRowLen:  319.00  ChainCnt:  0.00
Index Stats::
 ...
  Index: INX_EXTXXX3  Col#: 40
    LVLS: 3  #LB: 251775  #DK: 994  LB/K: 253.00  DB/K: 17075.00  CLUF: 16973517.00
  Index: INX_QUERYXIXX  Col#: 18
    LVLS: 3  #LB: 483492  #DK: 31264768  LB/K: 1.00  DB/K: 1.00  CLUF: 47778440.00
...
  Index: PK_IQUERYHISTORY  Col#: 1
    LVLS: 3  #LB: 407799  #DK: 56939871  LB/K: 1.00  DB/K: 1.00  CLUF: 51116553.00
Access path analysis for TAB_QWERTYUIOPAS
***************************************
SINGLE TABLE ACCESS PATH 
  Single Table Cardinality Estimation for TAB_QWERTYUIOPAS[O] 
  Column (#40): 
    NewDensity:0.000057, OldDensity:0.002967 BktCnt:254, PopBktCnt:240, PopValCnt:24, NDV:994
  Column (#40): EXXXX3(
    AvgLen: 7 NDV: 994 Nulls: 585162 Density: 0.000057
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 38

  Column (#18): 
    NewDensity:0.000000, OldDensity:0.000000 BktCnt:254, PopBktCnt:0, PopValCnt:0, NDV:31264768
  Column (#18): QUERYXXXX(
    AvgLen: 20 NDV: 31264768 Nulls: 0 Density: 0.000000
    Histogram: HtBal  #Bkts: 254  UncompBkts: 254  EndPtVals: 255
  Table: TAB_QWERTXXXXAS  Alias: O
    Card: Original: 58992346.000000  Rounded: 79668  Computed: 79667.56  Non Adjusted: 79667.56
  Access Path: TableScan
    Cost:  743146.94  Resp: 743146.94  Degree: 0
      Cost_io: 740517.00  Cost_cpu: 77421299057
      Resp_io: 740517.00  Resp_cpu: 77421299057
  Access Path: index (AllEqRange)
    Index: INX_EXTXXX3
    resc_io: 748296.00  resc_cpu: 8323150688
    ix_sel: 0.043441  ix_sel_with_filters: 0.043441 
    Cost: 748578.73  Resp: 748578.73  Degree: 1
  Access Path: index (RangeScan)
    Index: INX_QUERYXIXX
    resc_io: 1626415.00  resc_cpu: 13774888680
    ix_sel: 0.033700  ix_sel_with_filters: 0.033700 
    Cost: 1626882.92  Resp: 1626882.92  Degree: 1

******** Cost index join ********
Index join: Joining index INX_EXTXXX3
Index join: Joining index INX_QUERYXIXX
Ix HA Join
  Outer table:  TAB_QWERTYUIOPAS  Alias: O
    resc: 252234.49  card 58992346.00  bytes: 17  deg: 1  resp: 252234.49
  Inner table:    Alias: 
    resc: 483986.54  card: 58992346.00  bytes: 30  deg: 1  resp: 483986.54
    using dmeth: 2  #groups: 1
    Cost per ptn: 198690.65  #ptns: 1
    hash_area: 256 (max=262144) buildfrag: 208836  probefrag: 302451  ppasses: 1
  Hash join: Resc: 934911.67  Resp: 934911.67  [multiMatchCost=0.00]
******** Index join cost ********
Cost: 934911.67  
******** End index join costing ********
  Best:: AccessPath: TableScan
         Cost: 743146.94  Degree: 1  Resp: 743146.94  Card: 79667.56  Bytes: 0

***************************************

Note:
注意表有近6000万记录，谓词条件列EXXXX3有994 distinct值，可见重复很高，列上有等高直方图，从UncompBkts: 254 EndPtVals: 38 判断压缩后相差这么大判断，在254个桶中有些桶endpoint_value重复值较多，存在严重的倾斜情况。CBO计算全表扫的COST小于使用该索引，因为10053缺失这类信息，从DBA_HISTOGRAMS可以查看列的柱状图分布。

柱状图分布Height Balanced Histogram

查询视图DBA_HISTOGRAMS可以得到列的柱状图，在数据库不同的版本中视图列数可能不同。主要关注这几列

Note:
可见传入的变量值’001358‘刚好是柱状图的endpoint value, 但对应前面有10个桶，属于popular value, 高频值，这就导致CBO产生了比较高的COST值。

为什么执行计划变了？

前面我们有提到这个环境库启用了peek bind并禁用ACS自适应游标共享，可能是因为某些原因因为该SQL执行频率并不高，SQL被age out出shared pool， 在SQL再次执行重新reload回Shared pool里需要peek变量值，然后根据变量第一次的值生成执行计划，后面再执行相同SQL时，发现shared pool中存在相同文本直接使用第一次的执行计划，因为当前的ACS已禁用，当然如果ACS开着又可能会引入一些parse相关的问题如latch, version high..， 所以使用变量的SQL第一次传入的值就很关键，有一定小运气在里面，如果第一次传入的是低频值，那就用索引。 这个现象在大师Jonathan Lewis书中记录柱状图章节同样有提到。

Jonathan Lewis ‘s  《Cost-Based Oracle Fundamentals 》

Bind Variable Peeking
Of course, things got messier when 9i introduced bind variable peeking. Whenever a statement is
optimized, Oracle will (in almost all cases) check the actual values of any bind variables and
optimize the statement for those specific values.

PARSING AND OPTIMIZING
When an SQL statement is first executed, it has to be checked for syntax, interpreted, and optimized. Thereafter
if the same piece of text is fired at the database again, it may be recognized as previously used, in which
case the existing execution plan may be tracked down and reused.
However, even when a statement is still in memory, some of the information about the execution plan
may become invalid, or may get pushed out of memory by the standard memory management LRU routines.
When this happens, the statement will have to be reoptimized. (You can detect this from the loads and
invalidations columns in v$sql, summarized in the reloads and invalidations columns of
v$librarycache. Reloads occur when information is lost from memory; invalidations occur when some of
the dependent information changes.)
The reuse (or sharing) of SQL is generally a good thing—but if the execution plan generated on the first
use of a statement caters to an unlucky set of values, then every subsequent execution of that statement will
follow the same unlucky execution plan until you can force the statement out of memory—perhaps by the
extreme method of flushing the shared pool.
Bind variable peeking has the unfortunate side effect of making it very easy for one user to introduce an
execution plan that is bad news for every other user for an arbitrary amount of time, until that execution plan
happens to get flushed from the shared pool for some reason.

我们看一下SQL是否有AGE OUT出Shared pool。

SQL First Load

Performance metrics of child cursors of 4ruhsafdgfj0x while still in memory.

AWR

SGA breakdown differencez

• ordered by Pool, Name
• N/A value for Begin MB or End MB indicates the size of that Pool/Name was insignificant, or zero in that snapshot

Library Cache Activity

• “Pct Misses” should be very low

Note:
基本上可以判断当时有新的SQL执行，把执行频率少的SQL age out出内存，而刚好第一次传入的变量是一个高频值，选择了全表扫，后续所有的SQL继续沿用这个执行计划，直到人工执行了统计信息收集，使shared pool的该SQL 失效，再次解析时传入的值为低频的变量值，执行计划改为索引扫描。

打赏

微信扫一扫，打赏作者吧～