智能扫描引发Exadata性能问题

个人简介:石云华,Exadata中国用户组联合创始人,2019年被ORACLE官方授予ACE称号。毕业后一直从事Oracle数据库第三方运维服务工作,拥有十余年电信运营商、保险、税务、电力行业核心系统数据库运维经验。现就职于北京海天起点技术服务股份有限公司,oracle数据库专家组成员,Exadata部门负责人。个人著作有《Exadata实施运维指南》,另外一本《Oracle Exadata性能优化》即将面世。

案例概要:

我们的一个Exadata客户反映他们的跑批程序,在6月16号这天突然比平时慢了一个多小时,希望我们帮忙看看具体是什么原因引发的性能问题。

案例分析及处理:

客户将最近几天整个跑批程序中各个模块花费的大致时间展现给我们,具体如表所示。

日期 名称 开始时间 结束时间 持续时间(分钟)
2017/6/16 APP层结束时间 2017/6/16 6:17 2017/6/16 10:23 245.42
2017/6/16 MID_再保指标层结束 2017/6/16 3:43 2017/6/16 6:17 154.03
2017/6/16 MID_指标维度层结束 2017/6/16 2:01 2017/6/16 3:43 102.27
2017/6/16 MID_01层结束 2017/6/16 1:15 2017/6/16 2:00 44.48
2017/6/16 CD层结束时间 2017/6/16 1:00 2017/6/16 1:15 15.5
2017/6/15 APP层结束时间 2017/6/15 4:48 2017/6/15 8:42 233.62
2017/6/15 MID_再保指标层结束 2017/6/15 3:37 2017/6/15 4:48 71.58
2017/6/15 MID_指标维度层结束 2017/6/15 1:59 2017/6/15 3:37 97.82
2017/6/15 MID_01层结束 2017/6/15 1:11 2017/6/15 1:59 47.27
2017/6/15 CD层结束时间 2017/6/15 1:00 2017/6/15 1:11 11.77
2017/6/14 APP层结束时间 2017/6/14 4:53 2017/6/14 8:40 226.5
2017/6/14 MID_再保指标层结束 2017/6/14 3:40 2017/6/14 4:53 73.2
2017/6/14 MID_指标维度层结束 2017/6/14 1:58 2017/6/14 3:40 101.53
2017/6/14 MID_01层结束 2017/6/14 1:11 2017/6/14 1:55 43.82
2017/6/14 CD层结束时间 2017/6/14 1:00 2017/6/14 1:11 11.05

从如表中可以看出,正常情况下整个跑批程序基本上在每天的早晨8点半到9点左右结束,但6月16号延时到10点23分才结束,经排查可以定位到是”MID_再保指标层结束”模块所花费的时间有所变动,正常情况下,该模块基本上70分钟左右就可以完成,而6月16号该模块却运行了154分钟,整整慢了80分钟,这也导致整个跑批程序比平时慢了将近一个半小时。

进一步跟踪,我们定位到是”MID_再保指标层结束”模块中存储过程MID_AMT_SEGMENT中的一个sql语句出现性能问题(具体的SQL语句的SQL_ID为09m818v4zbqf4),该SQL语句对于整个存储过程而言至关重要,具体的SQL语句文本内容如下所示。

下面,需要进一步对比为什么相同的SQL语句在两天存在不同的性能表现,通过awrsqrpt.sql脚本获取SQL_ID为09m818v4zbqf4的SQL语句在14号的性能表现,具体信息如图10.16所示。


图10.16 该SQL语句正常时间段的信息

对于该特定的SQL语句(SQL_ID为09m818v4zbqf4),在14号的跑批期间执行了1次,花费了195445毫秒,其中CPU时间花费了193358毫秒,IO等待时间为1327毫秒,物理读为965996个数据块。

该SQL语句在16号的性能表现,具体信息如图10.17所示。


图10.17 该SQL语句异常时间段的信息

对于该特定的SQL语句(SQL_ID为09m818v4zbqf4),在16号的跑批期间执行了1次,但在信息抽取的期间内仍未执行完成,目前就已经花费了3663239毫秒,其中IO等待时间为1382870毫秒,物理读为7831175个数据块。

从14号和16号的信息中可以看出,这条SQL语句在这两天中执行计划完全相同,但在14号只运行了195秒,而16号运行了3663秒还没出结果。14号花费的时间主要在CPU上,而16号花费的时间CPU占用1641秒,IO占1382秒,同时还可以发现磁盘读也有很大的不同,14号只有965996个磁盘读,大约965996 *8k /1024/1024=7GB的数据量,而16号有7831175个磁盘读,大约7831175 *8k /1024/1024=59GB的数据量。

继续分析这个SQL语句的文本,该SQL语句主要是对MID_LOSSASS_KIND_ALL这张表进行分组,然后数据处理,这张表只有400多万条记录,而segment大小有7GB,没有lob字段的情况下,只能说明碎片非常严重,理论情况下,这张表应该只有几百MB的大小,注意一点,MID_LOSSASS_KIND_ALL这张表的大小为7GB,正好是14号物理访问的数据量,间接说明了16号除了全表扫描了MID_LOSSASS_KIND_ALL这张表的所有数据块之外,还访问了52GB的其他对象数据块。通过该SQL语句可以发现SQL语句中存在一个FN_DEFINITE_REGION函数,具体的函数定义如下所示。

从函数定义可以看出,需要访问CD_CODE_INTERVAL这张表,并且这张表的访问频率会非常频繁,上面那条SQL语句返回多少条记录,这个标量函数就需要执行多少次。

继续查看这个函数中所涉及的SQL语句在14号和16号这两天中的执行情况,其中14号的性能如图10.18所示。


图10.18 该SQL语句正常时间段的信息

在14号的凌晨4点至5点,这个SQL执行了6百万多次,但需要注意的是它总共才花费了477秒,同时该SQL语句基本上没有产生物理IO。

该SQL语句在16号的性能如图10.19所示。


图10.19 该SQL语句异常时间段的信息

在16号的凌晨5点至6点,该SQL语句才执行了1百万多次,但已经总共花费了3374秒,同时,物理IO占了35.6%。

看到这些信息,可以肯定SQL语句变慢,是由于标量函数中的select语句变慢导致,标量函数中的select语句从以前的477秒变成了现在的3374秒,接下来需要继续分析那个标量函数中的select语句出现了哪些变化,为什么会产生如此高的IO?

从图中可以看出标量函数中的select语句的SQL_ID为cbs42m8yb9gj2,下面查看dba_hist_active_sess_history视图,看看SQL_ID为cbs42m8yb9gj2的这个SQL语句在14号与16号之间有哪些变化,具体命令如下。

从以上命令输出可以看出,SQL_ID为cbs42m8yb9gj2的这个SQL语句在16号出现大量的cell smart table scan和enq: KO – fast object checkpoint等待事件,而该SQL语句在14号的等待事件基本为空。

SQL_ID为cbs42m8yb9gj2的SQL语句在14号的性能如图10.20所示。


图10.20 该SQL语句正常时间段的信息

SQL_ID为cbs42m8yb9gj2的SQL语句在16号的性能如图10.21所示。


图10.21 该SQL语句异常时间段的信息

可以看出,SQL_ID为cbs42m8yb9gj2的SQL语句在14号只有14个物理IO,而在16号8870590个物理IO,因此在16号物理IO等待的时间也非常长。

继续查看标量函数中的SQL语句所涉及的对象,具体信息如下。

可以看出,标量函数中的SQL语句所涉及的对象是一张非常小的表,只有几百条记录,表上没有任何的索引。访问次数极其频繁。

至此,整个故障的原因已经非常明显,标量函数中的SQL语句在14号进行了传统的数据访问方式,虽然每次都是全表扫描,但只产生了14个物理读,说明数据基本上全部缓存到SGA的BufferCache中。而16号进行了Exadata的智能扫描,每次都需要进行物理IO访问,非常表很少,但短时间内上百万甚至上千万的访问次数,导致产生了大量的物理IO。

通过前面章节的学习我们知道:① 对于OLTP类型的SQL语句不适合进行智能扫描。② 极小表在一般情况下不会触发智能扫描。

也许有人会问:为什么标量函数中的这个SQL语句会触发了智能扫描?其实是前期为了优化标量函数外层的那个insert into select语句(SQL_ID为09m818v4zbqf4),所以在insert into select语句之前加上了alter session set “_serial_direct_read”=always参数,增加了该参数后,对insert into select语句本身有帮助,会让该SQL语句进行智能扫描操作,但它导致的负面影响是标量函数中的SQL语句也触发了智能扫描操作,这反而导致了整个SQL语句的效率更加缓慢。

好了,最后还有一个疑问需要进行解释,既然alter session set “_serial_direct_read”=always参数前期就已经添加,但为什么前期一直没有问题,而只有16号才开始出现问题?为了回答这个问题,我们进行一个简单测试。

当SGA中未缓存数据时,执行select count(*) from mm where id=1;其10046事件生成的日志利用tkprof工具格式化后的信息如下。

当SGA中已经缓存了数据时,再次执行select count(*) from mm where id=1;其10046事件生成的日志利用tkprof工具格式化后的信息如下。

当SGA中已经缓存了数据时,在会话级别设置alter session set “_serial_direct_read”=always参数,再次执行

最后,我们清空SGA的shared_pool中已经缓存的数据,同时在会话级别设置alter session set “_serial_direct_read”=always参数,再次执行select count(*) from mm where id=1;其10046事件生成的日志利用tkprof工具格式化后的信息如下。

 

 

有没有发现,只有当清空了该SQL语句在shared_pool中的缓存后,在会话级别设置alter session set “_serial_direct_read”=always参数才开始生效。

通过这个小小的示例验证,基本可以解释为什么前期已经在会话级别设置了强制直接路径读取参数后,当时没有出现性能问题,而是在之后的某一天突然出现了性能问题。因为标量函数中的那个SQL语句访问极其频繁,所以它被刷出shared_pool的概率比较低,一旦它被刷出shared_pool后,再次进行硬解析时,则会强制进行智能扫描操作了。

案例解决方案:

撤销在会话级别设置的alter session set “_serial_direct_read”=always参数。

未经允许不得转载:Oracle一体机用户组 » 智能扫描引发Exadata性能问题

相关推荐