从一个索引问题的分析谈系统分析的全面性

最近这段时间人懒了很多，主要是写东西少了，我想从今天开始，每天腾出一点时间来写点东西，不一定是技术的，总之是写一点，和大家分享分享。闲话少说，今天给大家分享一个案例，这个案例在公司的公众号上分享过，今天重新编辑一下加入一些最新的感悟，再次发出来。

去年12月的一个周末上午9点左右，某银行的核心账务库突然出现性能问题，导致存取款业务受到很大影响。运维团队马上介入处置，发现表xxxx在插入数据时出现性能下降，造成交易停滞。运维团队在分析过程中，发现主要等待事件如下：

从中可以看出由于索引 争用引起的行锁占据前列，平均每次等待高达3秒以上。从而可以明确的定位索引冲突就是元凶了。于是运维团队开始处置相关的问题，试图解决索引冲突问题。不过采取的手段一一失效，最后在下午4点左右通过DISABLE了冲突相关的索引，暂时解决了问题。等晚上业务高峰期过去后，重建索引，第二天问题没有再现。

事故后，某国内知名数据库运维厂家派专家分析了该问题，，认为由于xxxx表上的索引出现大量的叶节点分裂分裂，导致索引写入性能下降是本次故障的主要原因。其主要依据是：

每秒的叶节点分裂居然高达34.32。用叶节点分裂来解释本次故障的原因也是说的过去的，老白以前就曾经遇到过类似问题导致系统变慢的案例。MOS上的文章Troubleshooting ‘enq: TX – indexcontention’ Waits (文档 ID 873243.1)也介绍了此类问题及其解决方案，通过重建索引，加大PCTFREE等方式来缓解此类问题。不过根据老白的经验，此类单边索引的分裂问题不会持续6-7个小时，而是会在一段时间内持续恶化，甚至导致系统出现类似HANG死的情况，但是如果过一段时间后，会有所缓解，于是当时对该结论表示了一些怀疑。第二天客户打电话给老白，希望老白能够帮助分析下这个案例。于是老白要来了AWR报告等进行了仔细分析。从负载报告上看：

于这套系统以前老白从来没有接触过，所以仅仅根据上面的数据无法判断系统是否正常，哪些地方不正常，偏差程度是多少，所以需要同时参考前一天相同时段的数据进行分析（当时系统基本正常）。在遇到一些棘手的问题需要分析的时候，故障时段的AWR报告对照正常时类似时段（一定要负载比较类似，否则比对效果就差一些），更容易发现其中的问题。

DB TIME和DB CPU的比例达到6:1以上，说明大量的数据库时间是处于等待状态，此时数据库状态是不正常的（前一天相同时间段内约为2:1，处于略高状态）。每秒REDO量、执行数、每秒事务数等也和平时也差不多。物理读的数量远低于8日正常时。

从缓冲池命中率看：

各个缓冲池命中率基本正常。

从TOP EVENT上看，前一天的数据是完全正常的，和出问题时段相比，有差别的地方是db file sequential reac的平均值为4毫秒，而出问题时候为5毫秒，比正常时候略差，LOG FILE SYNC Log file sync为2毫秒，而正常时约为1毫秒，似乎也说得过去。这一点十分容易让分析者忽略IO性能问题，老白当时也因此对IO问题没有多想，浪费了不少时间。而正常情况下，遇到这类问题，IO问题是首先不能排除的问题，甚至是需要首先去排查的，如果运维人员当时没有遗漏IO问题的分析，此次故障也不至于要持续到下午4点才解决。

既然是行锁等待，那么在应用上应该可以找到相关异常，此时我们需要关注TOPSQL的情况。

果不其然，一条INSERT语句居然排到执行时长的第一位，平均每次执行110ms+,这是极不正常的，因为普通的INSERT语句，在一个配置基本合理的系统上，平均执行延时不会超过20毫秒。于是老白猜测可能是XXXX表相关的表或者索引上出现了性能问题。从TOP SEGMENT的数据看：

ROW LOCK等待较为严重的段如下：

XXXX_IDX1的两个分区都排到了前五名，合计占总等待的比例接近20%。从热块冲突来看情况也是类似.甚至还存在部分ITL等待。

从上述数据可以看出，xxxx_IDX1存在的性能问题引起了本次故障。那么索引为什么会出现性能问题呢？是运维人员分析的索引叶节点分裂导致了索引索冲突吗？如果存在较为严重的索引叶节点分裂，确实会造成索引锁等待的时间增加，从而引起类似的性能问题，一般的常识是每秒叶节点分裂超过15,就说明叶节点分裂较为严重了。

从上面数据看，每秒叶节点分裂数达到34+，确实十分高，不过参考前一天的数据：

和出问题时段的叶节点分裂数据差不多。再参考一个使用类似银行核心系统的银行的数据（比较幸运的是老白曾在十多年前参与过该核心的研发，并且用户里也有一些使用同一个核心的其他银行）：

该数据来自于2017年，其业务量也小于本系统。而叶节点分裂数据同样很高，但是该银行的系统并未发生过类似问题。

从上述数据可以初步判断，本系统的索引叶节点分裂现象确实很严重，但是叶节点分裂可能不是造成本次故障的主要原因。那么产生该故障的主要原因是什么呢？必须还是先从SQL入手，看看什么情况下这条SQL的执行效率会比较低。

从上述数据看，这条SQL的平均执行时间小于1毫秒，而出现问题的时间段，这条SQL慢了50倍甚至数百倍。而从时间分析，主要的延时在并发相关等待。这和我们前面看到的现象是一致的，由于索引索冲突等待导致了该问题。

从上面的数据还可以看出，在12月8日的下午16点-17点之间，该SQL也出现了执行异常。通过分析比对正常时间段和异常时间段的AWR数据，发现一个问题，出现问题的时间段内，数据库的IO总量都存在一定的异常：

从上面的数据可以得到结论，故障发生时，存在RMAN备份，数据库的整体IO总量较大，达到每秒458M，其中433M来自RMAN备份。从表空间的IO延时情况来看：

有一些表空间的IO相应延时都处于不正常状态，甚至平均延时超过100ms。从数据文件来看，问题索引所在的表空间存在部分文件IO延时过高和BUFFER BUSY WAIT延时过高的问题：

IO延时过高是因为IO访问不均匀和IO访问量过大，以及系统总体IO过大导致，热块冲突是应用并发量过大、叶节点分裂、ITL等待等因素引起的。

从上述情况可以看出，在系统故障期间，数据库IO存在问题。下一步需要确认该IO问题是否和后端存储及操作系统层面有关。通过对OSWATCH数据的分析发现，在12月9日故障期间，操作系统层面存在大量的磁盘IO延时过高的问题,以下是节点1部分磁盘设备一天的平均IO响应时间，从中可以看出几乎所有盘的平均IO延时都是超过10毫秒的，说明从OS层面看，存储是存在较为严重的性能问题的：

从OSW的数据看，大多数盘的IO延时都是在AVSERV上的延时，AWWAIT等待基本为零，因此操作系统层面配置方面不存在明显问题，存储设备IO延时过高的主要原因是后端存储的问题。

至此问题十分明显了，本次问题的元凶是周末半夜的时候，本系统进行全备，由于本数据库已经超过13TB，因此0点开始的全备到第二天8点业务高峰开始的时候并未完成。于是备份与业务共同作用下导致了IO瓶颈的出现，最终导致了系统故障的悲剧。如果运维团队能够第一时间发现该问题，暂停RMAN备份（临时挂起），就可以很快解决该问题，恢复系统运行。而由于现场运维团队往往缺失整体分析的能力，对OS方面也不是很熟，所以很容易忽视这方面的问题，而很快从MOS上找到十分贴切的案例，根据这个案例的误导，最终导致悲剧。

目前我们的监控系统也往往都是偏于基于指标进行监控，不具备全局分析能力，从而导致监控系统在没事时候无用，有事时候更无用。传统的运维自动化系统提供了大量的指标和基线模板，但是这些基线模板往往和用户的系统情况脱节，无法直接使用。同时基线告警的数量可能高达每天几百几千，老白甚至见过一个用户，每天能够收到数万条告警信息。对于一个只有十来人的运维团队来说，对于这几万条告警信息，只能选择无视。如何让运维自动化系统智能起来，能具有专家的慧眼，才是运维自动化的发展目标，这也是这两年老白退出江湖，潜心研发深度运维工具D-SMART的最主要的原因。