记录一次执行计划恶化的处理过程

XLJ

相信大多数DBA都有过处理sql执行计划恶化的经验，今天分享的就是一次比较典型的案例：

（日期2016年3月9日）

公司处于快速发展期，唯一不变的就是变化本身了，高频率的新功能发布和优化容易造成数据库系统不稳定,前一晚正好是发布日而且有数据库的变更，所以今早起来就特别警惕，相信很多DBA都有这样的“习惯”吧，在路上的时候打开qq看看局势，不料发现一个同事6点20给我的留言，内容贴了sql_id和sql_text，并表示这句sql在1节点的执行计划比较高效，但在2节点的执行计划就低效，进行了绑定执行计划操作和剔除共享池，都无法生成正常的执行计划，希望我早上到公司关注一下，并附上了一张截图为证：

0uy16hrhspdxa文本如下(语句中的表做了脱敏处理)：

select *

  from (select rownum no_, A_.*

          from (select a.order_id as ACCEPTSEQNO,

                       to_char(a.acct_date, 'yyyymmdd') as ACCEPTDATE,

                       to_char(a.acct_date, 'hh24miss') as ACCEPTTIME,

                       (select to_char(decode(pay_money,

                                              '0',

                                              due_moeny,

                                              pay_money) * 100)

                          from t_xxx_ordfee

                         where order_id = a.order_id) as TXNAMOUNT,

                       'XXX商户' as MERCHANTNAME,

                       (select (case

                                 when l.prod_id = '111' then

                                  decode(a.order_type,

                                         'OT001',

                                         '01',

                                         'OT301',

                                         '03',

                                         'OT501',

                                         '04')

                                 when l.prod_id = '112' then

                                  decode(a.order_type,

                                         'OT001',

                                         '02',

                                         'OT301',

                                         '05')

                                 else

                                  'null'

                               end)

                          from t_pdm_action l

                         where l.action_id = c.action_id) as TXNTYPE,

                       '08' as TXNCHANNEL,

                       (select value1

                          from t_xxx_act_attr t

                         where t.actlist_id = c.actlist_id

                           and t.attr_id = '1016') as GOODSNAME,

                       decode(:1,

                              '01',

                              'XXX商户消费',

                              '02',

                              'XXX商户充值',

                              '其它业务') as TXNDSCPT,

                       decode(a.stat,

                              'S0C',

                              '00',

                              'S0A',

                              '01',

                              'S0F',

                              '02',

                              'S0U',

                              '03',

                              'S0D',

                              '04',

                              'S0X',

                              '05',

                              'S0G',

                              '01',

                              'S0T',

                              '06',

                              'S0R',

                              '07',

                              'null') as ORDERSTAT,

                       decode(c.action_id,

                              '140',

                              '04',

                              '141',

                              '04',

                              '138',

                              '02',

                              '147',

                              '03',

                              '154',

                              '05',

                              '156',

                              '06',

                              '01') as ACCOUNT,

                       a.act_stat as BUSISTAT,

                       a.pay_stat as PAYSTAT

                  from t_xxx_order   a,

                       t_xxx_actlist c,

                       t_xxx_info    b,

                       t_xxx_partner d

                 where 1 = 1

                   and c.order_id = a.order_id

                   and a.cust_id = b.cust_id

                   and b.prtn_id = d.prtn_id

                   and (c.action_id in

                       (select action_id

                           from t_pdm_action

                          where prod_id = '111') or action_id = '0')

                   and a.acct_date >= trunc(to_date(:2, 'yyyymmdd'))

                   and a.acct_date < trunc(to_date(:3, 'yyyymmdd') + 1)

                   and c.obj_code = :4

                   and a.order_type != 'OT101'

                   and a.order_type != 'OT601'

                   and a.order_type != 'OT501'

                   and a.order_type != 'OT502'

                 order by a.acct_date desc) A_

         where rownum < (to_number(:5) + to_number(:6) + 1)) B_

 where B_.no_ > to_number(:7)

 作为一个偏开发的DBA,对数据库中的对象和sql应该是比较了解的，该语句一般是用户在客户端发起订单查询时产生的，虽然执行总量不太高（从上面的截图就可以看出来，firstload时间点到现在运行的次数不多），但多张大表关联的执行计划异常势必会增加数据库的负载，而且根据用户活动规律，接下来几个小时内执行频率会明显升高，过了不多久收到系统监控短信，显示2节点的CPU超过50%了（近期把监控阀值从80%调整到了50%，这次调整现在看来非常到位，因为一般情况下CPU保持在15%以下，一旦到了50%基本可以判断有异常了，到80%再报的话显然太滞后了），几乎同时又收到数据库监控短信显示2节点有不少等待事件direct path write/read temp。由于是涉及temp表空间，我第一反应以为同事在创建索引，但是想了想，这操作昨晚应该执行完毕了，感觉不妙，难道和这句sql相关， 因为大表hash join也会使用temp表空间的，越想越慌，这情况严重了，别说客户体验，系统可用性都要出问题了

，下了地铁奔到单位，开机……

以上是在不登陆数据库的情况下就收获的信息，因为有了这些，可以直接下手处理了：

1. 看了眼等待事件先关sql，确实是这句！马上执行select * from table(dbms_xplan.display_awr('0uy16hrhspdxa',NULL,NULL,'ADVANCED'))

虽然sql文本和执行计划很长，没事，化繁为简、抓重点,用对比神器找找两个执行计划区别在哪里,左边是正常的2166885873的执行计划，右边是异常的3643373093的执行计划 ：                                                               

找sql本文中涉及t_xxx_order,t_xxx_actlist的语句：

  from t_xxx_order  a,t_xxx_actlist c,

                 where c.order_id = a.order_id

                   and a.acct_date >= trunc(to_date(:2, 'yyyymmdd'))

                   and a.acct_date < trunc(to_date(:3, 'yyyymmdd') + 1)

                   and c.obj_code = :4

简化完就好分析了：

正常的2166885873执行计划, t_xxx_actlist通过obj_code列上的IX_XXX_OBJCODE_A01索引过滤数据然后驱动t_xxx_order表，t_xxx_order通过关联列order_id上的主键PK_T_XXX_ORDER_TMP_01来访问；

异常的3643373093的执行计划, t_xxx_actlist通过obj_code列上的IX_XXX_OBJCODE_A01索引过滤数据，t_xxx_order通过acct_date列上的索引IX_XXX_ORDER_ACCTDATE_A01来过滤数据，然后两者做hash join，这造成效率低下，并且hash区域太大使用了临时表空间，造成direct path write/read temp等待事件。

2.稳定执行计划

  一般有几种办法

(1)绑定执行计划（sqlprofile SPM） 

(2)调整统计信息（收集新的统计信息、或者手工设定一个统计信息或者删除统计信息等）

(3)创建索引、不可见索引等涉及对象的操作 

(4)改写优化sql语句（包括添加各类hint），但这无法立刻实施并上线

按照方案优先级，我先实施了sqlprofile绑定：

实施是在2节点的，可以看到绑定是成功的，8点33是我实施的时间，而6点08则是我那位同事的实施时间观察了一下v$sql视图信息和display_cursor中的note，绑定确实没有生效，2节点依然使用异常的3643373093执行计划，情况比较紧急，这个问题再说吧（这个时候另外的同事在帮忙杀2节点运行着该sql语句的会话，降低系统负载）；

我立马使用二号方案，收集了一下涉及的索引的统计信息：

 exec dbms_stats.gather_index_stats(ownname=>'MEPF_DEV', indname=>'IX_XXX_ORDER_ACCTDATE_A01', estimate_percent=>10, degree=>4)

exec dbms_stats.gather_index_stats(ownname=>'MEPF_DEV', indname=>'PK_T_XXX_ORDER_TMP_01',estimate_percent=>10,degree => 8)

也没有作用（其实这个时候应该清空一下游标，不然收集统计信息并不能让游标立即失效，主要和dbms_stats的no_invalidate默认参数有关，所以说还是需要冷静下来啊）；

那就狠一点吧，启用方案三，这里肯定是让索引不可见，这个操作一般是不建议做的，因为这可能造成其他sql的执行计划恶化，可能是弊大于利的，但这个案列的情况不一样，t_xxx_order是分区表、它的acct_date列是分区字段，分区字段上的索引很多时候是一个大的干扰项，多次实际生产上血淋淋的教训啊，之后会有专门的分享来讲分区字段上建立索引导致的问题，那么乘此机会就干掉这个索引吧：

Alter index IX_XXX_ORDER_ACCTDATE_A01 invisible;

这里没有直接删除，不可见是比较保险的方案，它还在维护中的，可以瞬间变成有效状态，只是对CBO不可见了,此时是8点52分，至此故障处理完毕，期间CPU攀升到90%，最后恢复往日平静，实在要多险有多险,多亏大家反应迅速挽救了一次系统不可用的故障

当时2节点DB_TIME、系统各项指标、等待事件都很高：

CPU

DB time

IO

wait event

现在两个节点的该sql运行正常了，并且其他sql也没发生执行计划变化

另外提一下：

1. 该sql确实有优化的空间（几张大表都可以添加分区条件列从而使得在分区范围内进行扫描），这个之前已反馈并且开发也已完成优化，正在安排上线时间

2.  类似的查询以后将剥离本系统，这种大sql马上会寿终正寝

处理是结束了，但是有两个问题

1. 那么为什么会发生执行计划的变化呢？为什么就2节点？

2. 为什么sqlprofile无法绑定执行计划

好，我们来分析下原因：

可以看到2节点发生执行计划变化的时间是今天的0点16分

从监控告警验证一下，果然那个时候执行计划就变了（数据库监控做得越细越小，有时候这些信息还能方便DBA分析问题）

经过一番查询，发现t_xxx_aclist表的DDL时间和执行计划变化的时间完全吻合，

经过询问原来有同事在那个时候对t_xxx_aclist表进行了删除分区操作(数据归档)，基本可以断定这是导致sql重新解析的原因

对t_xxx_aclist的DDL造成sql重新解析，造成产生了新的低效的执行计划，访问了t_xxx_order表的其他索引

我们来看看t_xxx_order的统计信息

select column_name ,high_value,low_value,histogram from user_tab_columns where table_name='T_XXX_ORDER' and column_name in ('ACCT_DATE');

select

    a.column_name,

    a.num_distinct,

    display_raw(a.low_value,b.data_type) as low_val,

    display_raw(a.high_value,b.data_type) as high_val,

    b.data_type

 from

    dba_tab_col_statistics a, dba_tab_cols b

 where

   a.owner='MEPF_DEV' and

   a.table_name='T_XXX_ORDER' and

   a.table_name=b.table_name and

   a.column_name=b.column_name and

   a.column_name = 'ACCT_DATE'  

   and b.owner=a.owner

order by 1, 2;

可以看到t_xxx_order表的统计信息收集到1月25日， acct_date列的统计信息最大值也是1月25日，由于谓词越界效应,异常的3643373093的执行计划选择通过acct_date列上的索引IX_SCS_ORDER_ACCTDATE_A01来过滤数据就显得比较“合理了”

那么为什么1节点那个时候重新解析执行计划是正常的而2节点就是异常的呢，这个问题一般有两个可能

1. 初次解析带入的绑定变量不同，我后来看了下，2个节点代入的绑定变量差别不大

2. 是因为当时2节点在批量数据归档和创建索引，负载非常高(这个就不举证了，凌晨DBA在做相关变更)，这可能会造成CBO没有足够的资源来判断和选择最优路径，

个人觉得这个情况更有可能（去年也发生过某节点swap异常过高期间那个节点的某句sql执行计划就默认了一个隐式转换，走了全表扫描，而另外一个节点却正常，这个情况当时也是几乎无法解释，但主机组将swap问题解决后两个节点的sql就均正常了，没有隐式转换的问题了），

我个人感觉系统层面的负载会影响CBO，这里埋个点，欢迎各路大师踊跃留言指正

大家可能会说，那为什么ACS功能没生效呢，因为ACS要求列上有直方图信息，而这张表上没有直方图信息

至于为什么sql profile绑定无效呢?

从dba_sql_profile看绑定正常

select s.instance_number,s.sql_id,s.plan_hash_value,s.sql_profile,t.begin_interval_time

from dba_hist_sqlstat s,dba_hist_snapshot t

where s.sql_id='0uy16hrhspdxa' and s.sql_profile is not null

and s.snap_id=t.snap_id

order by t.begin_interval_time; --没有记录  证明没有生效

select * from table(dbms_xplan.display_cursor('&sql_id',null,'advanced')); --没有note证明没有生效

select sql_profile from gv$sql where sql_id='0uy16hrhspdxa'  --显示为空 证明没有生效

这个问题后来也搞清楚了，是因为这句sql的文本中有中文，绑定的时候出现了乱码，这里要强调一下规范了，sql本文里最好不用中文！

来看看绑定的脚本，出现了乱码……

more coe_xfr_sql_profile_0uy16hrhspdxa_2166885873.sql

通过plsql操作可以避免这个问题，或者像本次通过secureCRT操作，操作系统需要设置NLS_LANG变量