以前和一些年轻的DBA沟通的时候，他们总是对我们这种二十年前的DBA总去探究某些数据库内部实现机理感到不能理解。他们觉得现在要学的东西太多，学习各种操作和实施方案就够费劲了，还花那么多精力去细抠一些很可能八百年都用不上的屠龙技，意义并不大。确实，我们这些年在Oracle的一些内部原理方面的知识都是一些碎片化的屠龙技，不是遇到问题的时候，真的没有太多其他的用处。不过在一些复杂问题定位的时候，这些知识往往是找到解决问题办法的关键。
前阵子有个券商的系统出现了一次故障，交易在3秒钟左右的时间里出现了严重卡顿，影响到了几百笔关键业务的成交。为了避免类似问题再出现，领导希望找到根因。
图片
从AWR报告的TOP EVENTS上看到了几个疑点，分别是Log File SYNC、enq TX-INDEX CONTENTION和Control File Sequential Read。这三种等待确实都可能引发几秒钟的卡顿。当时驻场服务的维保厂商认定是log fie sync引发了卡顿，要去考虑如何优化REDO方面的问题。我看了这个等待后，第一反应是索引引发的行锁等待的可能性更大一些，因为平均延时够大。
3秒钟的抖动，在30分钟的报告里可能会被稀释。以前我也写文章谈过这个问题，宏观分析用AWR，而微观分析要用ASH。有经验的DBA一般会在这个时候导出ASH数据，然后在EXCEL里去做分析。在我们的DBAIOPS运维知识自动化系统中，就是通过ASH数据去做根因定位的。
图片
拿到ASH数据，第一步是删除与本次分析无关的列，然后另存一个文件。Oracle的ASH数据的列太多了，看起来很浪费时间。这是为了分析本次问题我留下的列。其实不同的问题分析留下的列会略有不同，但是大同小异。
图片
第二步就是对EVENT进行筛选，找出所有你需要分析的等待事件的样本。找出enq: TX - index contention等待事件的所有行，然后去发现规律。我们过滤出了400多行，数量不多，这对于定位问题是十分好的兆头。
图片
下一步把这些行拷贝到另外一个EXECL页里，进行进一步分析。接下来我们通过Blocking_session去找阻塞者，太幸运了。只找到一条记录。会话4756。
图片
这时候我们要回到原始文件中继续分析，注意：一定要回到原始文件，因为enq: TX - index contention还有个相类似的等待事件enq: TX - row lock contention，其最终影响是类似的。大多数阻塞都存在类似的问题。过滤阻塞会话为4756的会话，发现有426条。与当时400多笔交易受影响的现象十分吻合。
图片
下面就需要继续分析会话4756了。找出4756存在的问题，就找到了解决问题的钥匙。于是在原始表格中搜索4756会话。这个会话只有3条记录，是三个连续采样周期的数据，相隔一秒，3秒钟也正好与系统故障阻塞的3秒钟左右相吻合。看来这回是真正找到真凶了。
图片
在这里我们发现了一个十分奇怪的现象，这个会话实际上也在执行一条INSERT语句，而且是与被阻塞的会话的SQLID是完全相同的。从三个采样上看，这条SQL是一次执行持续了3秒钟，因为我们看到SQL_EXEC_ID是同一个。一条简单的单行INSERT语句持续执行了3秒钟，这太不合理了。看到等待事件，都是db file sequential read，USER/IO类的等待。
至此，问题分析的前半段就基本上明确了，问题基本上定位。但是为了防止类似问题再发生，必须找出根因。维保厂商给出的日志同步的结论基本上可以推翻了，虽然说LOG FILE SYNC也能解释某些INSERT缓慢的问题，但是4756压根没有等待过LOG FILE SYNC，所以不可能是日志同步引发的本次故障。
定位清楚根因对于彻底根除此类问题十分关键，因此本次分析尚未完成，还需要继续分析下去。可能上面的分析ASH数据的过程大家还常用一些，下面就要介绍一些不常用的技巧了。
图片
在Oracle导出的ASH数据的尾部，有很多十分有价值的 DELTA数据，就是两次采样之间，这个SESSION的一些开销。从这些开销可以推理出很多细微的问题来，对于定位问题十分关键。
从上面的数据里可以分析出，这个会话在执行这条INSERT的时候，产生了大量的物理IO，加在一起接近46M。案例说INSERT不应该产生如此多的物理IO的。这张表很热，INSERT所需要的大部分数据块（包含索引和表）都应该是在DB CACHE里的。其实在看到enq: TX - index contention这个等待事件的时候，我第一反应就是索引分裂。当时和用户DBA讨论这个问题的时候，也和他们一起分析了AWR报告里的叶节点分裂和枝节点分裂的统计数据，叶节点分裂大概每秒10个，枝节点分裂为0.2。叶节点分裂对于如此高并发的系统来说算是比较多的，但是还可以接受。不过枝节点分裂就有点过高了。
其实到这个地方，传统的分析过程已经完毕。下面就要依靠分析问题的人的知识是否足以支撑下面的推理了。因为后面只能靠推理，而缺少实际数据支撑了。要分析的问题是为什么一条简单的单行INSERT会产生接近50M的物理读。在我的知识体系里，索引维护可能是最有可能的答案了。如果索引的节点分裂的时候，需要写入新数据的前台进程需要负责维护这个分裂过程，如果索引中存在大量的碎片，那么在这样一次操作中可能会扫描大量的索引块，引发此类问题。这种情况往往在于使用很长时间没有维护过索引的系统中发生。但是本系统是一个券商的交易系统，这张表每个交易日结束都会TRUNCATE 的，因此这种情况不会发生。
那么下一种可能就是索引的“大分裂”，甚至可能是BLEVEL的重建，如果表足够大，而且数据足够冷，写入后不怎么访问。那么很可能重建BLEVEL的时候，很可能需要扫描很多不在内存中的索引块，从而引发这个问题。这张表正好又是交易日志表，在交易时间内，基本上写入后不会访问的，很符合这个条件。我觉得这个解释目前是最为合理的。因此如果要避免此类问题发生，把这张表做成HASH表可能是最佳的解决方案。
其实定位这个故障的最关键的一个拼图就是对Oracle数据库的前台进程维护索引的原理的理解，如果你不掌握这个知识，那么分析到最后的推理往往会发生偏差，从而影响根因定位。实际上在b-tree结构的数据库，比如MYSQL上，此类问题发生得更加频繁。以前我就帮助用户分析过几次MYSQL的简单INSERT 偶发性缓慢的问题，其原因和这个问题是十分类似的。
这些理论虽然可用的场景有限，不过如果你想成为分析问题的高手，还是需要去多学学数据库的一些基础理论，甚至理解到算法层面。今天这篇文章写得有点费劲，写到这里已经快9点了，后面还有些话好像没写痛快，不过还有其他事情要做，今天就先到这里吧。
