ITPub博客

首页 > 数据库 > Oracle > 这不仅仅是SQL优化!!--技术人生系列第五十五期-我和数据中心的故事

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

Oracle 作者:记录每一次错误 时间:2018-12-04 17:11:46 0 删除 编辑

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


      批量语句太慢了


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

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

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

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

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


再查看执行计划如下:

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


解决思路

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

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

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



       分析执行计划

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

分析执行计划:

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

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

  3. 关联方式使用的 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 执行非常慢;

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

  1. 执行慢,并不是执行计划的原因,而是多次执行的原因;

  2. 执行时快时慢,并不是涉及的单次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 文档如下:

关键点涉及几个:

  1. 分区表

  2. DML 操作

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

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


本文转载于中亦安图

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/31547066/viewspace-2284114/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
性格开朗,有较强的学习能力,对oracle数据库的体系结构,搭建RAC,timesten,goldengate,分布式数据库,dataguard,系统调优有较深入的了解, 尤其是oracle优化,深入学习的主机命令,对数据库的优化,SQL语句的优化有深入的认识,目前正在shell脚本,mysql,以后会有计划学习大数据和python。

注册时间:2018-07-23

  • 博文量
    182
  • 访问量
    324577