这不仅仅是SQL优化！-技术人生系列第五十五期-我和数据中心的故事

前言：通常SQL优化的常见手段包括，收集统计信息，创建索引，重写SQL语句，而大家日常遇到的CASE中是否也有遇到过，SQL已经看似没有优化空间，系系统整体性能也非常良好，但是SQL语句就是达不到预期执行效率的呢？今天作者给大家分享的就是一个不算SQL优化的“SQL优化"，希望大家能有所启发；

批量语句太慢了

某日早上，客户应用维护的同事提出问题，有一个每个工作日都执行的批量SQL语句执行速度太慢，如果不处理，恐怕以后会影响到联机开门业务；该SQL执行还有一个特点，虽然每天处理的数据量差不多，但是执行速度却时快时慢，快的时候可能1个小时左右执行完，慢的时候需要3、4个小时；具体SQL语句如下：

该语句并不复杂，是一个merge语句，涉及的表也不多，主要目的是将某个BANK_NO的相关数据归集到XXX_REST_INVM1_C表中；

通过相关脚本查看该语句的执行历史情况：

而从执行时间上看，该SQL在20180612当日执行时间从早上3点多执行到6点多，而20180610当日在一个小时内即已经执行完成；

再查看执行计划如下：

从执行计划来看，存在几个全表扫描和一个表的索引范围扫描，所有的关联方式都使用的hash join；

解决思路

1、优化执行计划，让SQL执行足够快，这样即使有差异，也不会感觉太明显；

2、如果无法优化执行计划，那么找到快慢的变化因素，让SQL以最快的速度运行；

那么，接下来该如何分析呢？经验丰富的你，看到上面的语句，是否有优化的思路呢？思考一下，精彩马上继续……

‍‍‍‍‍分析执行计划

‍‍‍‍‍

通常，我们说一个执行计划的好坏，是需要结合实际访问数据来评判的；在11g以后，oracle提供了一个很好的sqlmonitor的功能，对于大多数执行时间偏长的SQL语句，它都能记录非常详细的信息来帮助我们分析；这里我们sqlmonitor进行分析：

分析执行计划：

全表扫是否合适：从执行计划中的几个全表扫描来看，XXX_INVM1_B和XXX_REST_INVM1_C表返回的记录数较多，分别达到了2M和1M条记录，这里全表扫描是正确的；对于表XXX_DEPP_B，单个分区只有292条记录，占用空间也不大，这里走全表扫描影响也不大；

走索引的XXX_NAME_B表是否合适：从返回的记录数来看，大约在108K条左右，这里在返表后未再做filter，这里走索引也是合适的；

关联方式使用的hash join是否合适：从最终的返回记录数看，最后返回记录数在1M条左右，数据量偏大；而且从SQL逻辑来看，实际传入的参数只有一个BANK_ID字段，说明该merge语句是针对某一分行数据的集中处理，需要处理的数据量都会比较大；所以，这里使用hash join是合适的；

看起来执行计划的选择上来说，都没有太大的问题；

再仔细看看sqlmonitor的内容，Activity(%)这一列显示，在SQL执行过程中，merge过程占了整个执行过程的88.99%，而且从等待事件上看，该过程主要是在CPU上，还有少量的数据文件单块读；哦？难道是merge过程中有什么特殊的操作吗？难道问题在这里？

小小的插曲

从SQL文本来看，我们注意到update部分我们还能看到调用了FN_GEN_POSTNAME函数，从内容上看，该函数可能是导致merge部分CPU使用率特别高的原因之一；但是该函数内容主要为将传入的各个字段做拼接整合，并不涉及SQL语句的执行；事实上，我们从前面的sqlmonitor知道最终join完成后返回的记录数达到100万左右，对每条记录都执行一次该函数，执行纯数据/字符运算，消耗较多的CPU也是可以理解的，也就是说，这块的内容，其实并不能进行优化；

总的来说，就这个SQL语句的执行计划而言，看起来并不具备较大的优化空间！

既然优化执行计划的路子不通，那么接下来就先分析分析同样执行计划，同样业务数据量的情况下，为何时快时慢了；

换个思路

根据与应用维护团队的沟通了解来看，也以对该系统的业务特点来看，应该不存在单日数据量太大变化的情况，也正是因为SQL执行时间的不稳定，他们才提出了优化需求；

那是否某些情况下，系统IO情况缓慢或者其他原因呢？不如直接看看等待事件的分析来看：

我们需要注意的是，这里核查的是dba_hist_acitve_sess_history视图，该视图记录的是10秒一次采样的活动会话数据；

其中大量的ON CPU的记录，正是如sqlmonitor中显示的merge部分，以及几次hash可以join的过程理解；

少量db file scattered read的等待发生在几次做全表扫描的过程中；

而这里db file sequential read被采样的次数就有点偏多了，整个执行计划中，只有一次对表访问中使用了索引扫描而后回表操作，而这里显示db file sequential read的采样次数比db filescattered read要多很多，单独核查该部分的信息如下；

看起来，这部分主要是访问UNDO表空间了，嗯，只有看起来也许是在访问过程中构造一致性读导致的？不过，这里应该并不重要，毕竟占比还是不高，读写速度也还是正常的；

另外，我们对比分析6月12日和6月10日的等待事件，各种等待事件的比例是相当的，并不是因为异常等待事件过多而导致的时间过长；

而之前6月10日的sqlmonitor肯定是看不到了，所以我们也不能确定12日需要处理的数据量就一定比10日处理的要多；只不过在与应用沟通过程中，从历史数据的分析中，我们能知道最近每天需要处理的数据量是相当的；

如此看来，来分析解决这个问题的两个维度都已经没有前路了，该如何继续呢？盯着眼前的等待事件的，突然感觉之前似乎忽略了些什么，看来有了新方向！

转机

我们再来仔细看看等待事件的统计：

再对比此前的sqlmonitor信息：

你发现了什么吗？不妨停下来仔细看看，看看之前是漏掉了什么？想清楚了之后再往下翻哦……..

前面统计等待事件时，使用的dba_hist_active_sess_history视图；该视图的记录为10秒做一次采样，这里的采样超过800次，那么执行超过8000秒；而我们刚刚sqlmonitor中记录的执行时间好像没有执行那么久啊，原来并没有特别注意到sqlmonitor中的执行时间：

注意：事实上，如果我们只是查看dbms_sqltune.report_sqlmonitor(‘&sql_id’)，数据库会默认返回最近一次执行的monitor信息（前提是sqlmonitor中包含该次执行的信息）

仔细观察sqlmonitor的信息，可以发现，该次SQL的执行的开始时间是在06:25左右，执行时间也就持续1000秒左右，理论上这个执行速度是满足批量任务的要求的；

我们再换个角度看一下SQL的执行历史情况：

原来，从03:20开始，这条SQL在同一会话上连续执行了至少5次，执行的SQL_EXEC_ID是连续的，而且执行时间上看也是连续的；那是怎么回事呢？难道是对多个不同的BANK_ID进行了操作？我们继续通过sqlmonitor指定SQL_EXEC_ID来收集相关信息进行确认：

通过对多次执行过程的信息分析，我们可以看到每次其实执行的都是对BANK_NO为138的数据的处理！难道应用的调用或者调度出现了问题？同一事情做了5次？不过这5次的速度也不尽相同？

跟应用维护同事反复沟通，实际上这条SQL是在存储过程中执行的，上下文还有许多SQL需要执行，那些SQL不会在10秒内执行完成，即使是重复调用也就不会像我们前面看到的那么密集的在一个会话中重复执行；而且在应用的调用过程中，会记录对应的执行日志，这里也并没有记录对应的日志；总而言之，这条SQL只执行了一次，不应该出现这种情况……….

到这里，不用应用维护同事过多解释，其实作者心中已经差不多有了自己的答案，接下来需要的只是一步一步的确认而已！各位看官是不是也已经有了自己的答案呢？如果还没有，不妨停下来想一想………….

经验与验证

其实这里只是日常处理故障的经验的体现，处理到这里的时候，我才想起以前遇到过类似的案例，只是在没有注意到这些细节时是无法匹配上那次的经验的；我此前处理类似的案例时，查到过MOS上有一篇文档专门讲过SQL RESTART的；该文档的重点在于：如果你看到一条DML的SQL出现连续的SQL_EXEC_ID在一个会话上重复执行时，那么有可能是在执行该SQL的过程中，对应的SQL游标已经失效或者回滚段出现了无法扩展的情况，这个时候，oracle会自动重新执行该SQL；

那么这里可能出现了什么情况呢？我们首先检查SQL游标的情况：

这里可以看到，SQL的最近的解析时间是在06:25，也就是我们上面看到的最后一次执行的开始时间点；

我们的SQL最早在3:20就开始执行，而最新的解析时间是在06:25，显然这个过程中游标发生过失效；为什么失效呢？几个方面：统计信息收集，对表的DDL操作或者被挤出shared_pool区域，从这里看，正在执行的SQL应该不会被挤出shared_pool区域，而检查并没有发现涉及该SQL的表在3:00以后有统计信息收集的操作；不过，检查SQL涉及的几个表，我们能看到其中的XXX_NAME_B表确实在SQL的执行过程中做过数次对其分区的DDL操作：

至此，真相大白了，正是对于表XXX_NAME_B的DDL操作导致了SQL的不断重新执行，进而显得整个SQL执行非常慢；

前面我们提到的几点都有了解释：

执行慢，并不是执行计划的原因，而是多次执行的原因；

执行时快时慢，并不是涉及的单次SQL性能的好坏，而是执行次数的多少而已；

最后的小疑问

这里我们可能还会有几个小疑问：

Q：为什么重复执行几次，每次执行的时间长度还不一样，而且中间执行的某次已经大大超过了最后一次正常执行完成锁消耗的时间呢？

A：其实，除最后一次外，前面的数次执行都是没有完成的，而且在再次开始执行之前，需要进行回滚操作，通常来说，回滚的速度是偏慢的，而且执行持续的时间越长，回滚所需的时间也就越长，所以我们才看到上述情况；

Q：多次执行开始时间似乎与DDL时间并不完全吻合呀？

A：同理，在再次开始之前需要回滚操作；DDL只是触发cursor失效，然后开始回滚，回滚完成才能重新开始执行；

综合上面，我们又可以注意到前面提到的发生在UNDO表空间的‘db file sequential read’等待实际上是回滚过程造成的；

解决方案&总结

这里了解到是由于DDL造成的cursor失效继而导致SQL自动restart的情况，我们与应用沟通确认是由于另外的批量任务在执行完相关操作后，会对XXX_NAME_B表的各自分区进行truncate操作，truncate之后每天新的业务数据再往相关分区中灌入数据，而truncate操作实际上也是DDL操作；在了解到其实该表的各分区中记录数并不大未来也不会有大的增长后，建议应用修改对应的批量程序，将原来的truncate操作改成针对全表的delete操作，调整完成后观察到，该SQL在后续的执行中，每天只执行一次，执行时间也缩短到16分钟；

以往对于数据清理操作，特别是这种可以对无全局索引、整个单独分区的清理，我们都会建议使用truncate操作来完成，因为truncate通常更快，在批量时段对于SQL的影响也可以忽略，而delete操作相对来说执行时间会更久一些，通常还会占用一些undo空间；然而，从这个CASE来看，凡事不能一概而论，truncate对于SQL执行过程中的性能也不可忽略；

另外，关于这个CASE，主要关注的MOS文档如下：

关键点涉及几个：

分区表

DML操作

CURSOR的失效或者回滚段无法扩展的错误，该错误并不向用户抛出，而是直接restart这个SQL的执行；

实际上，这类CASE的触发除了上述条件外，还有其他条件，从ORA-14403的描述来看，这应该是针对以往版本的某个bug的修复后造成的现象，不过在该篇文档中未提及以往修复的bug，也不认为这里是一个bug。

往期经典回顾