本文作者:老K
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对语句进行分析;
语句逻辑读确实非常大:
通常来说,对于SQL性能问题,只需要理解SQL业务逻辑,分析一下SQL执行计划,然后充分了解相关各表的数据分布,就可以给出相应的解决方案;只不过,这一次留给老K时间似乎有些短,压力山大。
不过没有关系,按套路来,先看看语句内容和执行计划,然而,事情是这个样子的:
特点:
最大的特点是语句太长太变态;
执行计划中可以看到大量的union-all,可以判断SQL是由一系列简单的多表关联union而成;
涉及的表非常多,大约有30-40张表,表的大小约几十M到几个G不等;
表的连接方式各种都有,filter,nested loop,hash join,merge sort join,甚至merge join cartensian;
如果是你,你将如何进一步分析呢?
说话间,从开始查问题,到与应用沟通,大致看语句,了解执行计划,十分钟已经过去了,时间已经来到了8点10分,留给老K的时间已经不多了;除了执行计划,其他思考结果如下:
那么,这里,看起来我们目前能做的应该就是统计信息了,在短时间内没有办法分析SQL和SQL执行计划的情况下,收集统计信息应该是值得一试的方案;但是新问题来了,涉及上百张表,大的有几十个G,如果逐个收集统计信息,再先后重提应用报表SQL,估计又得损失几百万了。所以,到这里,我们需要做的事情是,找到那个最有可能有问题的表,收集统计信息,然后试着再重提批量,这里,时间紧迫,要求必须一击即中。老K需要闭上眼睛静静的思考一分钟,确实,在一分钟以后,老K想到了一个可以一试的思路,并且取得很好的效果!
OK,思考归来,老K的思路是,语句的逻辑读非常大,而以前执行较快,正常来说逻辑读不会太大,如果这里真的是某个表的统计信息不准的话,应该该表或者与该表关联的表的逻辑读会比较大(这一句很重要),而该段时间内主要就是这条SQL在执行,那么我们为什么不看看这段时间的AWR报告,看看是哪个表或者哪些表的逻辑读比较大呢?
问:这种方法每次都能准确找到统计信息有问题的那个表吗?
答:其实未必。这里还需要考虑驱动表与被驱动表的关系,篇幅原因,不作进一步解释。
问题是解决了,但是因为差点影响到业务开门,上面的领导还是比较关切,需要一个解释,或者说需要一个团队来承担这个责任,这中间几个关键点:
然而时间已经过了8点半,业务也均已开门,各新投系统和升级的系统也陆陆续续出现了一些小问题,需要在数据库方面进行排查;要给出这个解释暂时只能是口头上的,也许没有足够的时间进行验证。
通常来说,通过统计信息收集解决的问题,那无非就是统计信息过旧导致的;
但是这里有一个问题无法用统计信息过旧来解释:为什么以往一直没有问题,这次迁移到新的环境了,上来就有问题?是不是导入过程中有什么不该做的操作呢?
这里就需要仔细看看表的统计信息的收集时间了:
是不是很奇怪,老K顿感疑惑,不过通过数据导入日志确认了4月22日18:04这个时间点其实正是在dump的导入过程中之后,老K的疑惑也就解开了。
问:Why?
答:一般的表的导入顺序是:先导入表数据,再建索引等,最后导入统计信息;
问:答非所问啊,有关系吗?
答:非也。首先我们要想到的是4月22日是周六,默认自动统计信息收集的窗口范围内,在全库导入的过程中,XXDEALS表再表数据被导入后,到其统计信息被导入,中间的时间间隔是非常久的,那么这个时间间隔内,因为该表存在大量数据插入的情况,自动统计信息收集任务收集该表统计信息,在最终导入统计信息时,该表统计信息被从dump中导入的统计信息覆盖,这样刚刚收集的统计信息(4月22日)就成了历史,而4月7日收集的统计信息则成了当前的统计信息。
在确认完这个统计信息分析的时间轴后,老K就有理由做出下述完美的猜想了:
我们通过脚本查看SQL涉及的表的统计信息的最新时间,发现确实有部分表的统计信息分析时间是在导入完成之后,部分表的分析时间是在导入完成之前;这样看来,上述假设是极有可能的,基于上述可能,我们再次重申了我们对ORACLE数据库数据导入后对应用维护团队的操作要求:
在导入完成后,需要重新收集表的统计信息(可以按表或者按用户收集),其中,method_opt参数建议指定为repeat;
在与领导汇报完后,这口老锅算是甩的非常完美了^_^,老K继续匆匆投入到其他问题的处理当中,验证的事情可能需要留待后续来实现了。
到目前为止,我们分析到的问题可以捋一下:
时间空下来,想到如此完美的猜想,老K立即开始验证起来;现在,我们有了针对SQL前后的两个执行计划,可以通过对比结果来分析原因了;语句依然还是太长,基本没法直接读,但是确认了一点,语句确实是由union all组合了大量的较简单的多表连接来完成的。
我们收集了表XXDEALS的统计信息,那么我们主要关注执行计划中XXDEALS相关的部分的变化即可,然而,568行的执行计划,与XXDEALS相关的部分也有几十处,我们又如何能快速定位出导致逻辑读剧增的那部分呢?
小技巧:
首先我们确认表XXDDEALS只有700M大小,单扫一个表的逻辑读也不过是9万个逻辑读,即使是通过索引单次扫描一个表,表+索引一起最多也不过20万个逻辑读而已;
同理,如果是表XXDEALS作为驱动表的部分,即使是索引使用的变化,单次扫描导致的逻辑读增加也是不会太大的;
唯一能在单次查询中大规模扩大逻辑读的,是FX_FORWARDDEALS表从原来的驱动表变化为NL连接方式的被驱动表,或者FX_FORWARDDEALS作为NL连接方式的被驱动表使用的索引发生了变化。
遵循这个小技巧加上UE的文件对比功能,老K快速的找到了执行计划中变化的关键点:
较差执行计划中的FX_FORWARDDEALS:
然而,仔细分析两个执行计划,我们发现,其实驱动表的评估值并没有变化,评估出来的记录数都是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’时,两表评估的行数不一致;
另一方面,DEALS_0407直方图桶的个数是5个,那么它又是些什么值呢,我们不妨也简单看一下,确认一下是否确实是缺少了‘O’值:
考虑到在之前环境中,原SQL的执行是没有问题的,那么是不是说在原环境中对flagofdeal=‘O’的记录数评估应该是准确的呢?不如我们再来验证一下:
我们还是要回到评估行数的问题上来,为什么明明我们看到的直方图的记录中有‘O’值,11.2.0.4的优化器却认为直方图信息中没有‘O’值呢?难道是老K给出的get_external_value函数存在问题?这时,老K想起了在处理字符串的问题是经常会给我们带来视觉错误的一个问题,那就是空格,于是,我再次查询直方图信息:
基本上能确认是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.4 QUERIES USING CHAR FIELDS CAN PERFORM POORLY”,看起来与我们发现的情况非常符合,然而打开文章却并没有什么实际内容,看起来像是因为开SR而形成的bug文章;然而,仔细看该文章,可以注意到它实际指向了另一篇文章:
各位观众,读完获得了什么呢?
如果觉得我的文章对您有用,请点赞。您的支持将鼓励我继续创作!
赞1
添加新评论0 条评论