一个案例看Oracle的历史故障回放功 --技术人生系列第三十七期-我和数据中心的故事

11 月25日，周五晚上，正在家里看电视, 电话响了 ，是一位银行客户资深DBA的来电，也是我的好朋友、好兄弟，看来，他遇到麻烦了…

细心的同学，可能已经从这段话中发现了很多信息：

Ø    举例故障发生已经过去五天了，还可以查么？

Ø    故障只出现了不到1分钟，还可以查么？

Ø    简单的一笔INSERT INTO VALUES 怎么可能需要30秒呢?

在Oracle中，答案是YES！

而帮助我们完成这项核查任务的正是客户提到的ASH dump.

接下来这个case的根因分析，可能会颠覆很多人的运维“经验”，“没想到，这么做，对高并发的系统的影响这么大啊…”，还可能会有很多人生收获哦，我们不妨一起往下看吧。

打开邮件，不仅只有 awr 报告、 ash 报告，

还有一个表 ash_1120_2040 的dump,即ASH DUMP，真是贴心极了！

这个表实际上是 dba_hist_active_session_history 的备份， 该表按照 10 秒为粒度，记录数据库中活动的会话在执行的 SQL 和发生的等待，且不会随着重启而丢失。而 gv$active_session_history 则是按秒采样存储，但因为是存放在内存中，因此会随着重启而丢失，且保存的数量有限 .

这就是 ASH 功能，即活动会话历史功能。

将 ash_1120_2040 的dump导入电脑后，

立刻发出下列查询，获得按时间分布的活动会话个数的趋势 。

结果绘制为下图所示 ：

可以看到：

Ø    两个红色竖线之间的 30 秒左右，正是出现部分联机交易超时的时候。

Ø    但是在出问题前的几分钟，即红色加框部分，活动进程数已经上来了，这个和客户确认了一下，是批量调起来的时间，批量是多个进程并发处理的

接下来，我们发出下列查询，获得交易超时期间的等待事件

结果如下所示：

可以看到，都是和 RAC global cache 相关的等待 , 需要说明的是，不懂 RAC 也不影响对这个 case 的阅读和理解，小 y 主要是通过这个 case 传授给大家核查疑难历史问题的方法和思路，以及不断颠覆自己常识的勇气，才能不断进步。

可以看到 :

排在第一位的是 gc buffer busy acquire ， 表示数据库集群中的某个节点，如节点 1 向节点 2 请求一个 BLOCK 的时候，节点 1 已经先有人在我前面申请了同样一个 BLOCK ，所以连申请都是繁忙的， busy  acquire 。

这个等待说明什么呢？

两个或者两个以上的会话同时申请同一个 BLOCK ，撞上了。

常见原因：

通常和 SQL 的效率有关，如果 SQL 效率够高，则无需申请那么多 BLOCK ，就不会和其他会话撞在一起同时申请一个 BLOCK 去了。

但在这里，显然不是 SQL 效率的问题，因为他就是一条简单的 INSERT INTO VALUES 的语句而已，不存在执行计划不好的问题。

显然，在我之前的申请的那个进程，向节点 2 请求 BLOCK 的过程中遇到了异常，导致了问题的发生。

如果是你，接下来该怎么往下分析呢 ?

我们做根因分析，常用的手段就是梳理进程之间的关系。找到阻塞的源头后分析他在做什么，为什么比平时要慢很多，导致了问题的发生。

分析到了这里，也许有同学会问道，那 “我可以查到本节点是哪个会话在我之前申请了 BLOCK 么？我想去看看排在我前面的会话在经历什么 … ”

答案是 YES!！！

ASH 中的  blocking_session 字段标识了“哪个会话在我之前先行申请了该 BLOCK ”

接下来，我们发出下列查询，找到某一瞬间，正在等 gc buffer busy acquire 的上百个会话，分别在申请哪些 BLOCK(p1/p2) ，被谁阻塞了 (blocking_session) 。

可以看到，在开始出现问题的时刻，即 20:44:04

节点 1 有 82 个会话申请同一个 BLOCK 在等 gc bufferbusy acquire, 被节点 1 SID 为 3200 的会话阻塞了，即节点 1 SID 为 3200 的会话先于 82 个进程向节点 2 请求。

乘胜追击，我们看看节点 1SID 为 3200 的会话在等什么，被谁阻塞了呢？

如此递归下去，直到我们找到源头 , 到底是谁在“一夫当关，万夫莫开呢” …

结果如下：

可以看到：

异常出现了！节点 1 SID 为 3200 的会话在请求收到文件号 47  ， BLOCK 号 1540116 的时候，无法快速获取，等待事件是 gc current blockbusy, 并且这次申请从 20:44:04 到 20:44:24, 持续了 20 秒以上，但是崩溃的是，没有办法知道谁是我的阻塞者了 …

是的， ash 是一座宝藏，但是很多人却倒在了去挖宝藏的路上。

接下来，该怎么往下查呢？到底去往宝藏的路在哪里呢？

很抱歉，小 y 带着大家走了一遍这条死路，现实中，确实有很多朋友在不断重复这条死路，不想继续重复这条死路，想找一个带路人的，来参加我们的通向高手系列培训吧。

小 y 喜欢化繁为简，既然客户已经提到，有一笔插入报文表的联机交易 2016-11-20 20:44:04 ~ 20:44:34 ，时间达到了30秒。那么我们就从这里开始好了…

结果如下所示

可以看到：

SQL_ID 为 '15vru8xqgdkjf' 在ASH中被连续采样到了4次，说明执行时间大于30秒.与客户描述完全一致。然后呢？如果是你，怎么接着往下查，不妨思考几十秒…

接下来，我们通过 sql_exec_id 即 SQL 的唯一执行标记，来看看这笔超长交易的情况 ：

结果如下所示 :

确实，最长的一笔交易，在 04 秒到 24 秒期间，一直在等 ”gc current retry”

答案就在后面，什么时候往后翻，由你决定。

其实小 y 也不知道长交易的会话在等的那个人 ”  ”gc current retry” 到底是谁，因为“ gc current retry” 这个人，无论在度娘还是 GOOGLE 还是 METALINK 上都找不到任何解释。

这个时候，小 y 习惯于向生活要答案。

“gc currentretry” ，从字面上，看是请求当前 BLOCK ，但是无法获取，在 retry. 既然是向节点 2 请求一个 BLOCK ，无法获取，需要 retry, 那么我们有必要查下节点 2 是谁负责供应这个 BLOCK  呢？ 没错！就是节点 2 的 LMS 进程！

接下来，我们于情于理，都应该去查下问题期间， LMS 进程在做什么 …

发出下列查询即可

结果如下图所示

可以看到，这些 LMS 进程在等 gcs log flush sync, 即 LMS 进程在把一个 BLOCK 传给其他节点前，需要把这个 BLOCK 在 log buffer 中的改变，刷到磁盘中的在线日志文件，但是很可惜，刷了很长时间都没有完成。所以没有办法快速将 BLOCK 传输给节点 1 ，因此节点 1 在不断 retry. 这里 ” gcs log flush sync” 的阻塞者 2_2633 显然就是我们所熟悉的 LGWR 进程，即 log buffer  的写进程。

跨过了这道坎，显然，我们就可以一路南下，一马平川了！

接下来，看看节点 2 的 LGWR 进程是不是在忙其他事，无暇顾及 LMS 进程的刷日志请求呢？发出下列查询

结果如下所示：

可以看到：

节点 2 的 LGWR 进程，在等 enq: CF-contention, 即想要去写控制文件（例如切换日志时需要写控制文件），但是被其他人领先一步，这个人是节点 1 的 1369 会话。 期间， LGWR 进程傻傻的继续等控制文件的队列锁，但等了几十秒都无法获取。

乘胜追击，发出下列查询，看看节点 1 的 1369 会话为什么长时间持有控制文件的队列锁。

结果如下：

可以看到， sid=1369 是节点 1 的 ckpt 检查点进程

ckpt 正在进行控制文件的读写，因此持有控制文件的锁。

期间等待事件是控制文件的顺序度和并行写，并且没有阻塞，而是一直在变化。 正常来说，如果 IO 比较快的话，那么持有控制文件的锁的时间是非常快的 。

进一步检查 IO 的性能

从 oswatcher 数据可以看到，在问题时段，很多磁盘 busy 100%, 平均响应时间 200 多毫秒， IO 基本上主要是写 ，但不是所有盘都 100% ，例如 hdiskpower 11 依然是有少量读写的 。

检查大量写 IO 的来源

检查 ASH 中的等待事件

结果如下所示：

可以看到是问题时刻，在等 db file parallel write 的进程有 24 个，显然是 DBWR 进程在等 该数据库总计 24 个 DBWR 进程，全部处于活动状态，说明有什么动作触发了大量刷脏块的操作。

检查 alert 日志，可以看到 alter system archive log all （ current ）的命令，该命令必然会触发 DBWR 大量刷脏块，导致磁盘在短时间内极忙，导致 HBA 卡带宽也可能被占满。

到这里，大家不妨停下思考下，导致是谁执行了这个触发全量检查点的 archivelog all(current) 命令呢？

不妨思考几十秒…

答案就是我们大家所熟悉的 RMAN 备份脚本！

要说明的是，真相和你想的不一样！不是备份产生的 IO 影响了磁盘繁忙！

因为之前我们看到了，磁盘繁忙 100% 来自于写，而不是来自于读！ RMAN 主要是读！ 而且如果是 RMAN 的读 IO 影响磁盘繁忙，那么不可能只影响了 30 秒左右！

因为 RMAN 脚本开始执行时的 alter system archive log all （ current ）的命令触发了 DBWR 大量刷脏块，导致磁盘很忙，而控制文件和数据文件在一起，导致 ckpt 进程在拿到控制文件队列锁后，操作很慢，继而阻塞了 LGWR 进程， LGWR 进程于是不响应 LMS 进程，最后导致了 GC 等待数十秒，也就是联机交易大量超时。全量检查点完成后，交易恢复正常！

怎么再次验证呢 alter system archivelog .. 的影响呢？

接下来发出下面这条命令来验证下 ：

可以看到，  RMAN 就是在最初的 04 秒发起，之后的 43 分 34 秒往后 RMAN 进程都还在，但交易已经恢复正常，也就是说 RMAN 脚本里触发的全量检查点和批量并行写操作产生大量脏块叠加在一起，是问题的原因 ！

为什么以前没事？？

经确认，当天备份提前了，和批量重叠了，但不是因为 RMAN 备份的读 IO 导致问题，而是因为 RMAN 备份脚本在最开始执行的 alter system archivelog .. 命令触发的这次全量检查点和批量并行写操作产生大量脏块叠加在一起，导致 30 秒左右，检查的 INSERT 联机交易也出现了超时，这才是问题的真相和问题的根本原因！

你确认这就是问题的真相？

欢迎大家踊跃留言，说说你的想法，同时可以加小 y 微信  shadow-huang-bj ，一起加入学习探讨群 . 我将在下期（技术人生系列）揭晓答案。