The database instance Crash because the CPU High ?_数据库

某系统的其中一个 RAC 节点的 db 实例被干掉并自动重启了,如下是该实例的 alert log 信息:

The database instance Crash because the CPU High ?_linux_02

我们可以看到,该实例在13:17:07 秒被 LMS0 进程强行终止掉了,接着在13:17:17 被正常启动。在该实例被强行终止之前,有一点关键信息是值得我们注意的,如下:

The database instance Crash because the CPU High ?_数据库_03

从这部分信息,我们可以大致判断,在 13:16:56 时,Oracle 已经发现 LMON 进程长时间没有检测到心跳了,这个时间长达204秒。如果根据时间向前推进,在 13:13:32 时间点,实际上 Lmon 进程就开始出现异常了。 我们也可以看到在 13:13:45 时间点,出现了一个 ora-3136 错误。一般来讲,这个 waring 跟系统的负载可能有极大的关系,例如资源使用极高,可能出现超时的情况。

从 alert log 信息来看,Oracle 让我们去查看 LMD0/LMS0 以及 diag 的信息来进行进一步的分析。那么我们首先就来看一下 LMD0 进程的信息:

The database instance Crash because the CPU High ?_运维_04

从 LMD0 进程的信息来看,可以发现该进程(lmd0)已经等待了258秒,等待事件为 ges remote message,除此之外,没有其他的信息了。既然这样,那我们继续来看下 LMS0 进程的信息:

The database instance Crash because the CPU High ?_运维_05

LMS0 进程的信息似乎也没有太多的价值。最后我们只能看看 diag 的信息了,Oracle 在将所有进程 kill 之前进行了一次 dump。

The database instance Crash because the CPU High ?_linux_06

从前面的 load 来看,load 信息如下:loadavg : 62.17 35.29 18.12

这里简单解释一下,这3个 loadavg 值表示该主机分别在1分钟,5分钟,15分钟内的平均 load 值。 显然,这里我们不看后面2个指标了。根据时间点,我们这里看第一个 loadavg 值是62.17. 这个值已经超出 CPU 的数倍了,由此我们不难判断在13:16:56向前推进1分钟的时间内系统的 load 是极高的。

对于 LMON 进程,主要是监控 RAC 的 GES 信息,当然其作用不仅仅局限于此,其还负责检查集群中每个节点的健康情况,当有节点出现故障是,负责进行 reconfig 以及 GRD(global resource Directory) 的恢复等等。我们知道 AC 的脑裂机制,如果 IO fencing 是 Oracle 本身来完成,也就是说由 CLusterware 来完成。那么 Lmon 进程检查到实例级别出现脑裂时,会通知 clusterware 来进行脑裂操作,然而其并不会等待 clusterware 的处理结果。当等待超过一定时间,那么 LMON 进程会自动触发 IMR(instance membership recovery),这实际上也就是我们所说的 Instance membership reconfig。

对于报错中提到的 LMON 进程无法获得心跳了,那么 LMON 进程的心跳是什么呢? lmon 进程主要通过2种心跳机制来判断集群节点的状态:

1) 网络心跳 (主要是通过 ping 进行检测)
2) 控制文件磁盘心跳,类似 ckpt 进程每3s更新一次 controlfile 的机制。

那么什么情况下,会导致 LMON 无法获得心跳呢?

一般来讲有可能是该进程无法获得 latch 或者系统的资源不足,导致 LMON 进程无法正常工作。而这里我们也确实发现系统的 load 极高。

从上面的进程详细信息来看,我们也确实发现该进程一直在等待一个 latch,同时有其他的10个进程正在等待 LMON 进程,这其中的等待就包括 LMON, ASMB, ckpt 进程等等。从 diag 的 dump 来看,提示 lmon 进程已经等待了216秒。

从 process dump 我们还可以看到该进程一直无法获得的 latch 可能是被如下进程所持有:possible holder pid = 792 ospid=15095

不过可惜的是,我搜索 diag 日志,居然找不到 pid 792 这个会话。 我们知道 diag 的 trace 中的 process state dump 信息是根据 PID 排序的。我发现 dump 内容到 process 69 就结束了。从 PID 来看,该实例在出问题的时候,起码都 800个 process 以上,dump 的内容不可能只有这么一点。

从2节点的核心进程的日志也看不到有价值的信息。后面监控了一段时间发现该节点 cpu 几乎都是 90% 以上,很多时候甚至 100%。

检查发现是 CBC latch,而且都是一些报表的 SQL。

对于这个 case,我仍然感觉可能是资源异常导致 LMON 进程异常,最后 Oracle 检测到该进程长时间没有心跳,最终终止了该实例。

基于这个假设,我打算在自己的 VM Rac 环境 (Linux +10.2.0.5) 测试一下,如果某个节点 CPU 使用率极高的情况下,是否会导致 LMON 进程异常。

不过遗憾的是,我并没有模拟出这种情况,如下是我的模拟过程:

利用 shell 来模拟 cpu 的消耗:

The database instance Crash because the CPU High ?_数据库_07

调用该脚本即可:

[root@rac1 ~]# ./kill_cpu.sh 1
kill 17449 ;

这样测试了10分钟,发现 Rac 毫无反应,于是我又模拟了 latch: cache buffer chains. 以此来尽可能的将该节点的 CPU 消耗光。

The database instance Crash because the CPU High ?_运维_08

如下是该节点的 CPU 使用情况:

The database instance Crash because the CPU High ?_运维_09

我们可以看到在 08:43:16 到 08:46:44 之间,rac 节点1其实 hang 了很长时间,可惜这个数据库节点都没有挂。

只能说: Oracle 太强悍了!

------The End

配图来源:http://www.fitaacademy.com/courses/oracle-training-in-chennai/