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

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

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

可以看到，该 SQL 的执行计划一直使用的是 3134845891 ，近期未发生过改变；

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

再查看执行计划如下：

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

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

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

再仔细看看 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 中的执行时间：

仔细观察 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 执行非常慢；

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

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

本文转载于中亦安图