小y 黄远邦技术人生（18） ——记一条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”;
描述如下：