记一条500行执行计划的SQL问题分析-从应急处理到根因分析-技术人生系列第十八期

序幕 & 进入角色

4 月 24 日，早上七点，老 K 为迎接某国有大型银行批次投产后开门营业作现场支持该行运维团队的工作；根据以往的经验，该行每次批次投产会有数十套系统的软件 / 环境版本变化、系统迁移等操作，在投产后的第一个工作日开门营业后，多少会有一些问题；而 oracle 数据库作为各业务系统中的重要一环，往往是领导们关注的重点。

时间大约在 8 点左右，应用维护团队报出问题来：某套系统的某关键业务在开门前，需要先上送报表到某国家监管机构，报表主要就是通过在数据库中执行 sql 语句生成的；以往这个报表的生成时间只需要 2 分钟，而今跑了二十分钟也没有动静，重提了好几次也没有效果，而前端柜台业务开门时间是在 8 点半，必须要马上解决，避免影响到业务开门时间；

通过现场快速查看，系统整体无异常，只是业务报表的 SQL 执行时间偏长，主要运行在 CPU 上，看起来可能是逻辑读过大了，在分析间，老 K 也了解到该系统在这次批次投产过程中的变化；

关键信息：

数据库版本的升级和迁移，原版本为 10.2.0.5 ，现版本为 11.2.0.4 ；

使用数据泵导出导入方式进行迁移；

迁移时间是 4 月 22 日周六下午；

因为一些原因，原数据库所在系统已经 shutdown ；

在迁移完成后，数据库已经在昨天运行过一些其他的批量任务，无异常。

当前系统中主要就是该报表 SQL 在运行，没有其他联机业务 SQL ；

虽然这个报表 SQL 以前也运行过，奈何这是新的环境，原环境也已经不在，没法对比，看起来需要从头开始分析了；

老 K 首先通过 dbms_workload_repository.create_snapshot 做了一个 snapshot ，然后抓一下 awrsqrpt 对语句进行分析；

语句逻辑读确实非常大：

可以看到：

语句执行了将近 1300 秒，仍未执行完成；

逻辑读达到 4.5 亿；

通常来说，对于 SQL 性能问题，只需要理解 SQL 业务逻辑，分析一下 SQL 执行计划，然后充分了解相关各表的数据分布，就可以给出相应的解决方案；只不过，这一次留给老 K 时间似乎有些短，压力山大。

不过没有关系，按套路来，先看看语句内容和执行计划，然而，事情是这个样子的：

这样，老 K 就有几分方了，光是执行计划就达到了 568 行；再去看 SQL 语句内容，语句密密麻麻，操作终端上的 SQL 工具根本无法格式化 SQL 内容，基本也不具备可读性；简单看一眼执行计划，稍微能总结一些执行计划的特点：

特点：

最大的特点是语句太长太变态；

执行计划中可以看到大量的 uNIOn-all ，可以判断 SQL 是由一系列简单的多表关联 union 而成 ;

涉及的表非常多，大约有 30-40 张表，表的大小约几十 M 到几个 G 不等；

表的连接方式各种都有， filter ， nested loop ， hash join ， merge sortjoin ，甚至 merge join cartensian ；

如果是你，你将如何进一步分析呢？

快速做出决定 & 搞定问题

说话间，从开始查问题，到与应用沟通，大致看语句，了解执行计划，十分钟已经过去了，时间已经来到了 8 点 10 分，留给老 K 的时间已经不多了；除了执行计划，其他思考结果如下：

    1.语句应该是没有问题的，以前执行过，执行速度很快，说明该语句应该存在着一个好的执行计划 ;

    2.执行计划的变化一般能想到的情况是，统计信息不准，优化器参数变化，数据库版本变化；

       3.这里因为数据中心的相关标准，可以确定优化器参数是不会变化的，数据库的版本存在变化，统计信息可能存在变化或者不准的情况；

那么，这里，看起来我们目前能做的应该就是统计信息了，在短时间内没有办法分析 SQL 和 SQL 执行计划的情况下，收集统计信息应该是值得一试的方案；但是新问题来了，涉及上百张表，大的有几十个 G ，如果逐个收集统计信息，再先后重提应用报表 SQL ，估计又得损失几百万了 ~~ 所以， 到这里，我们需要做的事情是，找到那个最有可能有问题的表，收集统计信息，然后试着再重提批量，这里，时间紧迫，要求必须一击即中。 老 K 需要闭上眼睛静静的思考一分钟，确实，在一分钟以后，老 K 想到了一个可以一试的思路，并且取得很好的效果！

老规矩，亲爱的读者你也可以想象这样一个场景，摆在你面前的是上面的这样一个场景，你又会寻求什么样的思路来帮助你解决上面问题呢？需要思考前，不妨往上再翻一翻，看看都有哪些可以帮助到你的信息……

OK ，思考归来，老 K 的思路是，语句的逻辑读非常大，而以前执行较快，正常来说逻辑读不会太大，如果这里真的是某个表的统计信息不准的话， 应该该表或者与该表关联的表的逻辑读会比较大 （这一句很重要），而该段时间内主要就是这条 SQL 在执行，那么我们为什么不看看这段时间的 AWR 报告，看看是哪个表或者哪些表的逻辑读比较大呢？

可以看到， XXDEALS 表占比整库逻辑读的 92.35% ；

XXDEALS_IDX7 的逻辑读也达到了 1600 万；

所属用户也正是运行报表 SQL 的用户；

进一步检查可以知道，执行计划中的该表是存在的， 查看表的信息，大小大约 700M 左右，不算大，而且表的上次统计信息收集时间已经是 4 月 7 日，看上去距离当前时间也较久了 ；说干就干，开 8 个并行收集该表的统计信息；一分钟时间就收集完成，再重提批量任务，执行计划已经发生变化，执行完整个批量需要的时间大约就在 5 分钟左右 ;

最终，报表顺利上报，业务也基本准时开门，皆大欢喜。

我们看到，在这里的问题处理过程中，老 K 取巧了一下，在 SQL 语句和执行计划都非常长，无法在短时间内直接定位执行计划中所存在的问题的情况下，基于 SQL 执行时逻辑读非常高的特点，借助 AWR 报告中逻辑读 top 分布的情况，大致定位到可能存在导致执行计划不正确的表，并收集统计信息，最终解决了问题； ORACLE 提供了很多工具和方法来定位不同的问题，关键看我们能不能利用这些已有信息，发现信息中的特征来找到解决方法；

问： 这种方法每次都能准确找到统计信息有问题的那个表吗？

 答： 其实未必。这里还需要考虑驱动表与被驱动表的关系，篇幅原因，不作进一步      解释。

完美的解释 & 有意义的结论

问题是解决了，但是因为差点影响到业务开门，上面的领导还是比较关切，需要一个解释，或者说需要一个团队来承担这个责任，这中间几个关键点：

为什么报表 SQL 以往都没有问题，刚刚升级就出了问题，是什么原因。

应用维护团队告知投产期间未有大量数据变更的操作；

 明天或者更以后还会不会出现该类问题？

然而时间已经过了 8 点半，业务也均已开门，各新投系统和升级的系统也陆陆续续出现了一些小问题，需要在数据库方面进行排查；要给出这个解释暂时只能是口头上的，也许没有足够的时间进行验证。

通常来说，通过统计信息收集解决的问题，那无非就是统计信息过旧导致的；

但是这里有一个问题无法用统计信息过旧来解释：为什么以往一直没有问题，这次迁移到新的环境了，上来就有问题？是不是导入过程中有什么不该做的操作呢？

这里就需要仔细看看表的统计信息的收集时间了 :

可以看到，除最新收集的统计信息外， XXDEALS 表曾经收集过两次，一次收集时间是 4 月 7 日，一次收集时间是 4 月 22 日（也就是数据导入当天），然而在我们最近一次收集之前表的最新统计信息收集时间是 4 月 7 日，那么意味着表的统计信息分析时间轴是这样的：

  4 月 22 日   ---->  4 月 7 日   ----->  4 月 24 日

是不是很奇怪，老 K 顿感疑惑，不过通过数据导入日志确认了 4 月 22 日 18:04 这个时间点其实正是在 dump 的导入过程中之后，老 K 的疑惑也就解开了。

问： Why ？

答：一般的表的导入顺序是：先导入表数据，再建索引等，最后导入统计信息；

问：答非所问啊，有关系吗？

答：非也。首先我们要想到的是 4 月 22 日是周六，默认自动统计信息收集的窗口范围内，在全库导入的过程中， XXDEALS 表再表数据被导入后，到其统计信息被导入，中间的时间间隔是非常久的，那么这个时间间隔内，因为该表存在大量数据插入的情况，自动统计信息收集任务收集该表统计信息，在最终导入统计信息时，该表统计信息被从 dump 中导入的统计信息覆盖，这样刚刚收集的统计信息（ 4 月 22 日）就成了历史，而 4 月 7 日收集的统计信息则成了当前的统计信息。

在确认完这个统计信息分析的时间轴后，老 K 就有理由做出下述完美的猜想了：

假设两个表（A 、B），以前收集统计信息的时间点相差不大，比如都是 4 月 7 日左右收集的；

在将 A 、 B 表在 4 月 24 日统计信息收集任务时间窗口导入到新的数据库中；

A 表先被自动收集统计信息，后导入旧的统计信息，那么 A 表的统计信息就是 4 月 7 日的统计信息

B 表的收集时间较靠后，导入完成时统计信息是 4 月 7 日，而后才进行统计信息收集，那么统计信息的收集时间则是 4 月 24 日；

最后，我们可以认为， A 、 B 两表在原库中统计信息是一致的，而在新库中则可能会出现 A 、 B 两表的统计信息出现较大偏差的情况；

 这样， SQL 中 A 、 B 两表关联，则极有可能在新旧两库中执行计划不一致的  情况。

我们通过脚本查看 SQL 涉及的表的统计信息的最新时间，发现确实有部分表的统计信息分析时间是在导入完成之后，部分表的分析时间是在导入完成之前；这样看来，上述假设是极有可能的，基于上述可能，我们再次重申了我们对 ORACLE 数据库数据导入后对应用维护团队的操作要求也是我们的结论：

在导入完成后，需要重新收集表的统计信息（可以按表或者按用户收集），其中， method_opt 参数建议指定为 repeat ；

在与领导汇报完后，这口老锅算是甩的非常完美了 ^_^ ，老 K 继续匆匆投入到其他问题的处理当中，验证的事情可能需要留待后续来实现了。

到目前为止，我们分析到的问题可以捋一下：

  SQL 执行时间长，逻辑读过大；

通过 AWR 报告快速定位到逻辑读较大的对象；

通过收集逻辑读较大对象的统计信息；

重新执行 SQL ，正常完成 ;

 我们在查询过程中，了解到，导入时正好赶上了系统的统计信息收集时间  窗口，而这个过程可能会导致在新环境中多个表的统计信息关系发生变  化，进而导致执行计划发生变化；

化繁为简 & 简单验证

时间空下来，想到如此完美的猜想，老 K 立即开始验证起来；现在，我们有了针对 SQL 前后的两个执行计划，可以通过对比结果来分析原因了；语句依然还是太长，基本没法直接读，但是确认了一点， 语句确实是由 unionall 组合了大量的较简单的多表连接来完成的 。

我们收集了表 XXDEALS 的统计信息，那么我们主要关注执行计划中 XXDEALS 相关的部分的变化即可，然而， 568 行的执行计划，与 XXDEALS 相关的部分也有几十处，我们又如何能快速定位出导致逻辑读剧增的那部分呢？

首先我们确认表 XXDDEALS 只有 700M 大小，单扫一个表的逻辑读也不过是 9 万个逻辑读，即使是通过索引单次扫描一个表，表 + 索引一起最多也不过 20 万个逻辑读而已；

同理，如果是表 XXDEALS 作为驱动表的部分，即使是索引使用的变化，单次扫描导致的逻辑读增加也是不会太大的；

 唯一能在单次查询中大规模扩大逻辑读的，是 XXDDEALS 表从原来  的驱动表变化为 NL 连接方式的被驱动表，或者 XXDDEALS 作为 NL  连接方式的被驱动表使用的索引发生了变化 。

较差执行计划:

较好的执行计划：

从执行计划分析，符合我们上述的小技巧，如果使用 hash join ，原则上两表只需要执行一次扫描，而如果是 NL ，则可能会因为驱动表估算的行数不准而导致被驱动表的逻辑读大增；

从变态的 SQL 语句中搜索出对应这段执行计划的 SQL 大致如下：

并通过使用加 hint 的方式执行该语句让其跑出两个执行计划对比起逻辑读和执行计划，可以验证这段 SQL 确实是导致整个 SQL 执行效率大大下降的原因； 就这样，我们通过执行计划的分析，将纷繁的 SQL 分析化解为简短的两表关联的分析；

然而，仔细分析两个执行计划，我们发现，其实驱动表的评估值并没有变化，评估出来的记录数都是 1 ，那么我们上面的完美猜想还能在这里得到验证吗？

并不能！ 我们看两个执行计划中， b 表作为驱动表，评估的返回记录数均是 1 ，并不会影响到被驱动表 XXDEALS 的连接方式（ NL 还是 HASH JOIN ）的选择，也不会影响 XXDEALS 使用索引的选择；同时，我们也确认，   b 表和 XXDEALS 一样，统计信息也是从原库中导入过来的，表分析时间是在导入之前； 所以，猜想在这里只是凭借经验，似乎也合理的一种解释而已，并不是最后的事实。

根据上述分析，这里我们又可以进一步简化；两个执行计划中，驱动表的位置和评估行数都没有变化，那么我们唯一需要关注的是在较差的执行计划中，为什么会使用 NL 呢？

即，我们需要关注的就只剩下表 XXDEALS 在相关 maturitydate 条件和 flaGofdeal 条件下，为什么一个会走索引，而另一个却没有走索引，与统计信息的关系又如何?

精确定位问题

要精确定位问题，在这里可能需要重现问题。这里其实要重现问题比较简单，老 K 通过 dbms_stats.restore_table_stats 恢复表的统计信息，并将新旧表的定义（包含了统计信息又不用导数据）各导出一份，导入到 11.2.0.4 的测试环境中去，分别命名为 DEALS_0407 和 DEALS_0424 ，两表分别使用的是 4 月 7 日的统计信息和 4 月 24 日的统计信息，也可以基本反映两个日期中表的数据分布情况。

通过简单测试，我们又把 maturitydate 字段的影响给排除掉了，现在唯一的区别就在与使用 flagofdeal=‘O’ 时，两表评估的行数不一致；

那么这里 317 和 455K 都是怎么算出来的呢？我们试着看看 10053 能不能给我们一些帮助 ;

DEALS_0407 的 10053 关键评估信息：

DEALS_0424 的 10053 关键评估信息：

我们可以看到，两表总行数上（ Original ）的区别不大， flagofdeal 列的密度（ Density ）有一些区别，最主要的是区别是两表 flagofdeal 列 Frequency 直方图的桶数量（ Bkts ）居然不同， DEALS_0407 只有 5 个桶，而 DEALS_0424 却有 6 个桶；

老 K 简单一算，对于 DEALS_0407 最终估算的 317 不正是等于 1017318 （ Original ） *0.000311 （ Newdensity ）吗？这样看来，显然 ’O’ 值并不在直方图的 popular value 中了；

而 DEALS_0424 中，最终估算的 455K 条记录则像是其 popular value 中估算出来的了；如果真的是这样的话，那么基本是可以确认是因为数据变化，即 DEALS_0407 表中没有 ’O’ 值记录，而在 DEALS_0424 中则大量插入 / 修改了 ’O’ 值记录了。

然而，这一次，有了充分的时间，老 K 就不再轻易下结论了！

 

首先，我们来验证 DEALS_0424 的估算值是否准确：

其中 get_external_value 数据来为自定义的转换 endpoint_value 为实际字符串的函数，已经发布在 “ 中亦安图”公众账号中，有需要的朋友可以关注中亦安图公众号，回复 “ 直方图函数 ” 获取；

我们看到， ‘O’ 值的 endpoint_number 为 14164 ；

那么其评估值即为： 1021005 （ Original ） * （（ 14164-7839 ） /14177 ） =455K

与 10053 trace 和执行计划中的都一致；

 

另一方面， DEALS_0407 直方图桶的个数是 5 个，那么它又是些什么值呢，我们不妨也简单看一下，确认一下是否确实是缺少了 ‘O’ 值：

然而，结果似乎不如我们所愿， DEALS_0407 虽然确实是 5 个桶，但是却是包含了 ‘O’ 值的；使用同样方法去估算 ’O’ 值的记录数应该差不多是 465K ：

看起来，确实在迁移升级期间没有那么大的数据的变化；

那到这里，问题又是什么呢？

进一步定位

考虑到在之前环境中，原 SQL 的执行是没有问题的，那么是不是说在原环境中对 flagofdeal=‘O’ 的记录数评估应该是准确的呢？不如我们再来验证一下：

没错，我们看到，如果我们再 SQL 中增加 OPTIMIZER_FEATURES_ENABLE('10.2.0.5') 的 hint 让数据库使用 10.2.0.5 的优化器的话，是能正确的评估出该 ’O’ 值记录的行数；

同样，即使是 11.2.0.3 的优化器，也同样能正确的评估出 ’O’ 值记录的行数：

如此，老 K 更是迷惘了，难道单单 11.2.0.4 有问题，那是为什么呢？

 

我们还是要回到评估行数的问题上来，为什么明明我们看到的直方图的记录中有 ‘O’ 值， 11.2.0.4 的优化器却认为直方图信息中没有 ‘O’ 值呢？难道是老 K 给出的 get_external_value 函数存在问题？这时，老 K 想起了在处理字符串的问题是经常会给我们带来视觉错误的一个问题，那就是空格，于是，我再次查询直方图信息：

没错，就是空格，其实在转化成字符串后，发现，两者还是有区别的，我们再仔细对比的话，其实两表直方图的 endpoint_value 确实是不一样的；我们又通过对比同表的其他字段直方图信息确认了，一般如果实际值一样，在信息里的 endpoint_value 应该是一样的：

最后，通过多次确认测试，最终定位到只要列的类型为 char 类型，而且字段长度低于 8 ，那么会出现在 11.2.0.3 （及更低版本）与 11.2.0.4 的直方图信息 endpoint_value 不一致；测试过程此处不表；

定位bug

基本上能确认是 oracle 的一个变化，至少是 11.2.0.3 到 11.2.0.4 之间的一个变化；接下来的任务就是找到 ORACLE 官方的说明来，之前老 K 也查了几次 MOS ，也许是因为定位的还不够精准，导致在 MOS 查找的关键字不够 “ 关键 ” ，每次都是搜出一大堆结果却无法逐一细细阅读而毫无收获，这次老 K 上 MOS 使用关键词 “char endpoint_value different” 进行搜索，很快就找到了文章 “ Bug 18550628 : AFTER UPGRADE TO 11.2.0.4QUERIES USING CHAR FIELDS CAN PERFORM POORLY ” ，看起来与我们发现的情况非常符合，然而打开文章却并没有什么实际内容，看起来像是因为开 SR 而形成的 bug 文章；然而，仔细看该文章，可以注意到它实际指向了另一篇文章：

查找 18255105 ，找到的文章是“ Patch for upgrade scripts to identify histograms affected by fix ofbug 15898932 ” ;

描述如下：

收获了什么

各位观众，读完获得了什么呢？反正，老K是获得了许多，累了就不多说了。

本文转载于中亦安图