Oracle的一次Cache buffers chains等待事件排查过程

题记

这是某移动运营商在SQL线下审核项目中，协助开发商完善数据库性能的过程。以往开发商遇到此问题总是怀疑是数据库的Bug，试图尝试重启Tuxedo、Weblogic，严重时甚至重启实例来缓解问题。经过下面的详细分析，你会发现事实并非如此。

详细诊断过程

这是对于两个节点的RAC环境，数据库版本为11.2.0.4 for HP-UX IA（64-bit）。在2014年11月5日16点至18点间，节点一的CPU使用率从平时的40%增长到60%左右，部分业务办理缓慢甚至超时。经过详细分析，发现是一个低效的、高并发的核心业务的SQL语句引起的。

通过询问业务人员得知，业务系统从17:00至17:30感觉慢得更为明显，因此我们导出了该时间段节点二的AWR报告。

下图显示了实例名为crmdb21的采样时间、数据库版本、CPU个数和内存大小等概要信息，通过简单的换算DB Time和Elapsed可知（2807.24/29.7=94），这台64 Cores的小型机的确很忙。

Load Profile中的Logical read（blocks）973915.2/Per Second表明平均每秒产生的逻辑读blocks数约为97万，每秒的逻辑读约有7.6GB（973915*db_block_size=7.6GB/s），一般来说，逻辑读高CPU的使用率也会随之升高，通常会在Top 10中出现诸如latch: cache buffers chains、db filescattered read等事件。

在Top 10Foregrand Events by Total Wait Time的部分，可以看到在该时间段的主要等待事件是latch:cache buffers chains 和 db filesequential read。它们的%DB Time分别占到38.9%和24.3%。后者代表单块读，是一种比较常见的物理IO等待事件，通常在数据块从磁盘读入到相连的内存空间中时发生，也可能是SQL语句使用了selectivity不高的索引，从而导致访问了过多不必要的索引块或者使用了错误的索引，这些等待说明SQL语句的执行计划可能不是最优的。前者是导致数据库逻辑读高的根本原因，由此推断某个或者某些SQL语句出现了性能衰变。

在接下来的SQLStatistics部分，分别截取了SQL ordered by Elapsed Time和 SQL orderedby Gets，可以发现SQL Id=g5z291fcmwz08的语句分别占了42.50%的DB Time和35.19%的逻辑读，而其他SQL所占的DB Time和逻辑读分别在0.1%～5%。由此可以确定，就是该SQL语句影响系统性能，但还需要详细了解该SQL的执行计划、绑定变量和当时的逻辑读等信息。

通过分析可以导出该SQLReport。记录了故障时间段SQL Id=g5z291fcmwz08的SQL概要信息。

执行统计信息如下：

可以发现该SQL在30分钟内执行了2281次，单次的逻辑读在267755.03，由此很可能认为这个SQL始终没有走到合适的索引或者是全表扫描。值得关注的是267755.03这个数字，它是一个平均值，很有可能被平均，换句话说，有时单次逻辑读很小、有时可能还会大于这个平均值。

我们再看执行计划：

1、Rows或Cost仅代表一个估算值。

2、谓词条件中用到的索引列都是绑定变量，在遇到绑定变量+窥视关闭（该数据库窥视关闭）时，即使有直方图信息，优化器在估算时总是认为数据分布是平均的。

3、在扫描索引PK_CM_CU_INDIDUAL时，扫描了1到14个分区。

4、CUSTOMER表返回的记录数稍有偏差，将会增加与PK_CM_CU_INDIDUAL索引循环的次数，也会影响整个查询的性能。

执行计划中，先通过索引IDX_CUSTOMER_CERTID过滤出2条数据，之后回CUSTOMER表得到1条记录，再通过结果集去驱动查询主键PK_CM_CU_INDIVIDUAL，最后通过嵌套循环返回结果集。看上去每一步的Rows和Cost都非常理想，实际上存在4点值得关注的隐患。

在继续往下分析之前，开发人员抛出一个疑问，为什么同一个SQL在其他两个库都正常，而在这个库却出现了问题？

通过以下查询不难发现，这个SQL在每一个库的单次平均逻辑读都相似。

执行统计如下：

从执行次数上看，其他两个库基本维持在几十或上百次，而在故障库中峰值高达2281次，这同样是故障点的执行次数。这表明该SQL的性能是低效的，对数据库造成的性能冲击也是随着执行次数的增加而愈演愈烈的。

谓词条件中用到了绑定变量，需要找到当时的绑定变量值来看真实的执行计划。

在上述分析中提到，“如果CUSTOMER表返回的记录数稍有偏差，将会增加与PK_CM_CU_INDIDUAL索引循环的次数，从而影响整个查询的性能”。在回表之前先通过索引字段CERTID过滤数据，该字段的数据分布非常重要。即该字段的值是否存在数据倾斜至关重要，下面对其进行统计。

结果很明显，该字段使用过的值出现了严重的数据倾斜。我们把3xxxxxx00402045代入WHERE条件，通过/*+gather_plan_statistics*/查看优化器的估计值与真实值之间的差异。在扫描IDX_CUSTOMER_CERTID索引时，估算值是1，而实际值是59106，回表之后的记录数依然是59106，这表明至少要和下面的索引关联59106次，被驱动表恰巧共有14个分区，循环的次数就变成了59106×14 次，这也是单次逻辑高达2503731的原因，如图9-10所示。

说明：/*+gather_plan_statistics*/这个提示会记录每一步操作中真实返回的行数（A-Rows）、逻辑读（Buffers）和耗费的时间（A-Time）。

同时也测试了一个不倾斜的值进行对比（3xxxxxx00402044），发现逻辑读只有760，这说明了该SQL被执行的次数越多，逻辑读就会被平均得更小

经过以上分析可知，数据倾斜、全分区扫描、执行次数三者相加之和的增加使得该SQL的性能影响了整个系统。接下来从两个方面对其进行优化。

1、从SQL方面。

编写一个新SQL专门针对倾斜值，用HASH JOIN替代默认的NEST LOOP。

2、从业务方面。

1）检查倾斜数据的合理性。

2）在访问PERSON_CUSTOMER表时，可以增加分区字段加以限制，从而避免扫描多余的分区。

3）梳理业务场景。

通过和开发人员、业务人员反复沟通确认，该条SQL在业务场景和数据倾斜上都是可以修正和清理的。在完全满足业务场景的前提下，开发人员对SQL做了调整，通过改写union all和rownum <2，有效合理地控制了返回的记录数，逻辑读也从26万降低到了1303，性能提升了近200倍，如图9-12所示。这个案例的优化过程也是围绕技术和业务反复优化的过程。

总结

在移动运营商SQL审核项目的交付过程中，和大家分享以下几点。

1、在AWR、SQL Report中Per所对应的往往是平均值，需要结合执行计划和数据分布来分析该平均值是否真实可靠。

2、当全分区扫描出现在执行计划中时，需要结合业务判断其合理性。

3、绑定变量的历史值和其数据分布能够提高分析问题的精确性。

4、提高SQL的性能存在着多种优化方法，随着系统本身和系统架构的推进，SQL优化需要结合技术、数据特点、业务场景等要素综合分析，从而才能给客户提出一套完整、全面、可执行的优化方案。

参考

【谁影响了性能】全面诊断Cache buffers chains