DB time抖动的原因分析

杨建荣 2015-09-22 16:10:00
9月22日,”DBA+社群“开讲啦!由搜狐畅游高级DBA杨建荣在“DBA+北京群”进行了一次关于DB time抖动的原因分析的线上主题分享。小编特别整理出其中精华内容,供大家学习交流。
 
 
 

 

嘉宾简介
 
 

 

杨建荣,Oracle ACE-A,YEP成员,现就职于搜狐畅游,拥有6年以上的数据库开发和运维经验,曾任amdocs DBA,负责亚太电信运营商的数据业务支持。擅长电信数据业务,数据库迁移和性能调优。

 

拥有Oracle 10g OCP,OCM, MySQL OCP认证,对shell,java有一定的功底,曾在2015年数据库大会进行关于数据迁移和升级的主题分享,现在每天仍在孜孜不倦的进行技术分享,每天通过微信,技术博客共享,已连续坚持550多天。

 

演讲实录
 
 

 

DB time抖动的原因分析-1

 

本次演讲主要分享了DB time 抖动的诊断案例,主要分为四个部分:1、问题背景;2、DB time监控中发现的抖动;3、问题分析;4、问题总结。

 

问题背景

 

 

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

 

DB time抖动的原因分析-2

 

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

 

DB time抖动的原因分析-3

 

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

 

DB time抖动的原因分析-4
 

简单来说,DB TIME= 所有前台session花费在database调用上的总和时间。

 

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

 

DB time抖动的原因分析-5

 

这个时候进行了第二层定制,结合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抖动的原因分析-6

 

DB time监控中发现的抖动

 

 

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

 

DB time抖动的原因分析-7

 

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

 

DB time抖动的原因分析-8

 

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

 

DB time抖动的原因分析-9

 

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

 

DB time抖动的原因分析-10

 

问题分析

 

 

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

 

DB time抖动的原因分析-11

 

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

 

DB time抖动的原因分析-12

 

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

 

DB time抖动的原因分析-13

 

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

 

DB time抖动的原因分析-14

 

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

 

DB time抖动的原因分析-15

 

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

 

DB time抖动的原因分析-16

 

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

 

但是在源库中尝试添加物化视图日志却报出了错误,ORA-12000: a materialized view log already exists on table 'USER_BASIC_TEST‘

使用快速刷新和默认的刷新选项,速度都很快。这个时候基本可以排除物化视图刷新的影响了,感觉问题的排查到了山穷水尽的阶段。

 

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

 

DB time抖动的原因分析-17

 

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

 

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

 

DB time抖动的原因分析-18

 

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

 

DB time抖动的原因分析-19

 

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

 

DB time抖动的原因分析-20

 

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

 

DB time抖动的原因分析-21

 

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

 

DB time抖动的原因分析-22

 

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

 

DB time抖动的原因分析-23

 

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

 

DB time抖动的原因分析-24
 

问题总结

 

 

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

 

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

最新评论
访客 2020年02月09日

写得很好,码字评论支持一下

访客 2020年02月08日

你截图给你妈看呢

访客 2020年01月25日

不错,很详细

访客 2020年01月24日

怎么下载或者在哪找得到?

访客 2020年01月14日

001

活动预告