DB time抖动的原因分析案例分享(r6笔记第67天)

杨建荣 2016-10-25 19:22:41
今天来给大家分享一下DBtime抖动的诊断案例。讲到的不足之处还希望大家多多指正,共同提高。案例会分下面几个方面来说。

首先来说问题的背景。因为使用的数据库环境多且复杂,数据库不只有Oracle,所以通过gc来统一管理所有的数据库平台定制成本较高,使用zabbix可以满足系统级监控和MySQL等的监控报警,对于Oracle的监控通过扩展的Orabbix来实现。

而DB time这个监控项还是比较经典的一个指标,基本是作为DBA查看awr的首选指标。这个指标如此重要,但是似乎Oracle没有提供一个很有效的监控方式。如果逐一从awr报告中抓取就有些麻烦了。下面是一个awr报告中DB time的例子。

而什么是DB time,我引用了Oracle John Beresniewicz的解释

好了,明确了DB time,首先我们进行了第一层定制,这是在定制后得到的DB time情况,得到的是快照点的对应的DB time,比如快照36343~36344,持续60分钟,DB time为85分钟,以此类推。
得到这样的DB time列表,还是可以发现很多潜在的问题,可以充分结合awr来进行诊断,但是不足之处还是后知后觉。

这个时候进行了第二层定制,结合v$sys_time_model来和快照中对应的DB time进行关联,得到一个相对接近的DB time值。
比如快照在下午1点的DB time为100(转换为秒),我在1点5分的时候通过v$sys_time_model得到一个DB time值160,然后和1点整的DB time值相减,得到的负载情况就是(160-100)/(5*60)=20%

这是一个两天之内的DB time汇总图,可以看到DB time的一些抖动情况

这个图可以看到DB time在短时间内发生了抖动,可以抓取到比较精确的时间点。

上面的图中我们选用蓝色框中的时间段来具体分析问题,而下面的图是监控数据库中的并行进程的情况,可以看到问题时间段内,并行进程高达100多个。

同时,也收到了报警的短信,提示在问题时间点,确实有150多个active session.


通过这些信息和图表,我们可以得到这样的猜想,可能是在特定的时间段内触发了特定的scheduler导致了这个问题。

对于这个问题的分析,我是分为4个步骤来一一排查的。

首先查看数据库日志,日志中没有发现任何的异常信息。

接着抓取ASH报告,在服务端使用tns连接到数据库实例,生成的ash报告中的top等待事件如下。
而对于标红的等待事件查看metalink说问题可以忽略,奇怪的是ash报告中也得不到任何相关的sql.这里有个潜在的操作问题,先卖个关子。

既然数据库日志,ash中都得不到有效的信息,那么我们的猜想就自然落到了scheduler上,结果一查看,还确实有几个scheduler在问题时间段内执行。

这时候感觉问题已经定位了,我们抓取离问题时间段最近的一个scheduler,可以看到其实这个scheduler就是在做一个物化视图刷新,那么问题很可能在于物化视图刷新上了。

进一步验证,发现这个物化视图的源表在另外一个数据库中,通过db link连接访问。而源表的数据有2亿多条。这个时候猜测感觉应该是物化视图走了全量刷新导致了性能的抖动。

但是在源库中尝试添加物化视图日志却报出了错误,ORA-12000: a materialized view log already exists on table 'USER_BASIC_TEST‘
使用快速刷新和默认的刷新选项,速度都很快。这个时候基本可以排除物化视图刷新的影响了,感觉问题的排查到了山穷水尽的阶段。

既然短时间内存在大量的并行,但是通过日志,ash报告,scheculer中的物化视图刷新都没有找到更多的信息,我开始尝试自己定制监控策略。于是我写了上面的脚本。来定时从数据库中抓取这些并行的信息。

写了这个脚本之后,在后台去跑,每5秒钟检查一次,执行10个小时,这样在第二天上班的时候就能够得到详细的报告了。

第二天查看的时候,果然发现还是有收获的,得到了并行进程的执行情况,列举出了一小部分,而且最重要的是我们定位到了对应的sql_id

我们来看看这个语句,这个sql结构比较简单,表中的数据量也很大,但是执行计划却走了全表扫描,按照where查询条件是应该走索引的。
查看索引发现确实是存在的,为什么存在索引,查询也满足索引触发的条件,但是查询却走了全表扫描呢?

查看分析发现,有部分的分区索引竟然是unusable状态,明白了这一点,解决起来就非常简单了,我们可以rebuile索引分区修复。
我们先排除并行的影响,使用Hint no_parallel来看看rebuild分区索引前后的执行计划的情况。



下图是在rebuild index partition前后的语句执行计划的情况,可以看到rebuild之后,马上走了索引扫描,

索引失效导致了全表扫描,而对于并行的问题怎么解释呢。进一步分析,发现这个表的并行度是DEFAULT(注意第2个查询语句中DEFAULT前的几个空格)
如果并行度为DEFAULT就会依赖于CPU资源,所以可以看到48,96的并行度。而这个default的由来其实是因为我们使用了类似下面的语句。
ALTER TABLE TEST_BILLDETAIL PARALLEL 导致了大量并行的问题。

明白了这点,问题解决就引刃而解了,我们可以限定一个较低的并行度或者设置并行度为默认的1,
最后来说一下为什么ash没有抓取到数据,大家可以仔细分析一下这个操作记录,是在服务端同一个窗口中执行的。
其实问题就在于主备切换后,使用tns连接到testdb1其实是连接到了备库,所以得到的ash报告才没有抓取到任何的sql语句,这个问题很可能会误导你。


当然这个问题修复之后,可以看到DB time的抖动变得平稳了。而且并行资源的使用也不会爆发式增长,箭头和框图都可以看出,都基本达到了一个相对合理的范围区间。


通过这个例子可以看到一个DBtime的抖动可能对于DBA来说可能意味着性能的抖动,我们根据这些细小的变化发现很多的潜在问题。这种分析问题的方式就可以达到先知先觉,对于异常操作的感知度也会更加灵敏。因为这个分析过程没有用到awr和ash(想用没用上J),所以可以进一步尝试扩展为自动化的分析。

最后吐槽一下,这个问题的排查中自己也好几次准备放弃,首先就是想当然认为应该是有什么Job在运行导致的问题想就不查了,然后ash报告因为操作失误没抓取到合适的数据,接着自定义脚本的时候最开始漏了sql_id,结果格式混乱,结果又多耽误了一天。不过最后的结果还是可以让人接受的。所以希望大家在分析问题的时候也可以坚持一下,多细心一些。

 

最后感谢DBA+社群提供的这个平台和机会,大家多多交流。