某RAC数据库一个节点“宕机”原因分析
某RAC数据库一个节点“宕机”原因分析
优化团队中一同事接到通知，北京一套RAC数据库在7月1日早上9点多“宕掉了”，具体是所有的机器都宕掉了，还是其中的某一个节点宕掉了则不详，需要去排查才知。
经过对该RAC的相关的log和nmon进行分析，查明为“伪宕机”，真正原因为：第2节点对外服务的网络没有了流量，服务器被人为重启。下面为分析过程。
一、先把经过分析得出来的故障经过贴在这里，便于读者快速的了解此次过程的前因后果：
顺序
时间
现象描述
1
8:00:00
二号节点的Public网络流量突然降为0，但没断线，一直持续到二号节点关机时
2
9:39:59
二号节点服务器被关机，后经查，使用的命令是"init 0"
3
9:40:18
一号节点发现和二号节点的心跳出现了问题
4
9:40:32
将二节点从CRS中移除出去
5
9:40:32
重构CRS，CRS中只保留了第一节点
6
9:40:36
将原本属于二号节点上的两个VIP迁移并注册到了一号节点
7
9:45:13
二号节点服务器起动起来了
8
9:49:42
二节点CRS启动
9
9:50:24
CRS再次重构已经启动，将二节点加入CRS中
10
9:51:10
再次关闭二节点CRS
11
10:47:45
二节点CRS再次启动，并已经加入到CRS中来
二、详细分析过程
1、RAC基础信息
节点
主机名
public IP / VIP（eth2) priv IP (eth3) 1 XXXXdb7 10.X.XX.80/10.X.XX.82 192.XX.XX.80 2 XXXXdb8 10.X.XX.81/10.X.XX.83/10.X.XX.84 192.XX.XX.81
2、查看第1节点（XXXXdb7）的日志信息
2.1、第1节点（XXXXdb7）的OS messages：
Jun 30 04:03:06 XXXXdb7 syslogd 1.4.1: restart. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Registering new address record for 10.X.XX.83 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Withdrawing address record for 10.X.XX.83 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Registering new address record for 10.X.XX.83 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Withdrawing address record for 10.X.XX.83 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Registering new address record for 10.X.XX.83 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Registering new address record for 10.X.XX.84 on eth2. Jul 1 09:40:36 XXXXdb7 avahi-daemon[9246]: Withdrawing address record for 10.X.XX.84 on eth2.
分析：
（1）09:40:36，本属于第2节点的10.X.XX.83/10.X.XX.84两个VIP地址，被飘移到了第1节点的eth2网卡上，最少说明第2节点的CRS宕掉了
（2）无任何软、硬件错误日志
2.2、第1节点（XXXXdb7）CRS_alert log：
2013-07-01 09:40:18.629
[cssd(9742)]CRS-1612:Network communication with node XXXXdb8 (2) missing for 50% of timeout interval. Removal of this node from cluster in 14.290 seconds 2013-07-01 09:40:25.663 [cssd(9742)]CRS-1611:Network communication with node XXXXdb8 (2) missing for 75% of timeout interval. Removal of this node from cluster in 7.250 seconds 2013-07-01 09:40:30.673 [cssd(9742)]CRS-1610:Network communication with node XXXXdb8 (2) missing for 90% of timeout interval. Removal of this node from cluster in 2.240 seconds 2013-07-01 09:40:32.920 [cssd(9742)]CRS-1632:Node XXXXdb8 is being removed from the cluster in cluster incarnation 249439701 2013-07-01 09:40:32.940 [cssd(9742)]CRS-1601:CSSD Reconfiguration complete. Active nodes are XXXXdb7 . 2013-07-01 09:40:33.902 [crsd(10300)]CRS-5504:Node down event reported for node 'XXXXdb8'. 2013-07-01 09:40:44.683 [crsd(10300)]CRS-2773:Server 'XXXXdb8' has been removed from pool 'Generic'. 2013-07-01 09:40:44.684 [crsd(10300)]CRS-2773:Server 'XXXXdb8' has been removed from pool 'ora.XXXXc'. 2013-07-01 09:50:24.410 [cssd(9742)]CRS-1601:CSSD Reconfiguration complete. Active nodes are XXXXdb7 XXXXdb8. 2013-07-01 09:51:10.792 [cssd(9742)]CRS-1625:Node XXXXdb8, number 2, was manually shut down 2013-07-01 09:51:10.831 [cssd(9742)]CRS-1601:CSSD Reconfiguration complete. Active nodes are XXXXdb7 . 2013-07-01 10:47:45.660 [cssd(9742)]CRS-1601:CSSD Reconfiguration complete. Active nodes are XXXXdb7 XXXXdb8
分析：
（1）09:40:18.629，第1节点发现与第2节点XXXXdb8(2)的心跳网络已经不相通;
（2）连续三次心跳失败后，第1节点认为第2节点已经出现故障，将第2节点从集群中移除;
（3）09:40:32.940重构了RAC，集群中只保留一个节点（第1节点）
（4）在此已经完全知道了是第2节点先出现问题了。
3、查看第2节点（XXXXdb8）的日志信息
3.1、第2节点（XXXXdb7）的OS messages：
Jul 1 09:39:59 XXXXdb8 shutdown[8014]: shutting down for system halt Jul 1 09:40:00 XXXXdb8 pcscd: winscard.c:304:SCardConnect() Reader E-Gate 0 0 Not Found Jul 1 09:40:02 XXXXdb8 smartd[10533]: smartd received signal 15: Terminated Jul 1 09:40:02 XXXXdb8 smartd[10533]: smartd is exiting (exit status 0) Jul 1 09:45:13 XXXXdb8 syslogd 1.4.1: restart.
分析：
（1）在09:39:59，2节点服务器被关机，到此为止，已经知道服务器被关机过了
（2）最需要引起注意的是，关闭服务器之前，服务器并没有报出任何与软、硬件相关的告警信息，说明软、硬件都是正常的
3.2、第2节点（XXXXdb）CRS Alert log：
2013-06-30 23:00:19.744 [ctssd(11038)]CRS-2409:The clock on host XXXXdb8 is not synchronous with the mean cluster time. No action has been taken as the Cluster Time Synchronization Service is running in observer mode. 2013-07-01 09:49:42.394 [ohasd(10803)]CRS-2112:The OLR service started on node XXXXdb8.
分析：
在9:49:42，CRS在二节点上被启动，在启动CRS之前，没有任何CRS关闭的LOG，也没有CRS相关的报错信息，这个问题就比较严重了，说明CRS不是被正常关闭的，很有可能是因为服务器被自动或人为强制重启的，才导致CRS根本就没有写CRS关闭的LOG
4、到此判断服务服务器被重启的原因应该只有三个（第2、3点在经分析后被排除）：
1、 人为重启了服务器
2、 服务器负载过高引起的2节点DOWN机或被1节点所驱逐所引起的DOWN机，这点经过仔细分析，发现2节点在09:39:59 就关机机了，而1节点在09:40:18 才发现与2节点网络心跳连接不通了，说明2节点并不是被1节点所驱逐而引发重启的，那是不是因为2节点的负载过高所引起的重启呢，经过分析2节点的CPU、IO、Memory负载一直很低、很平稳，所以这种应该不是致使服务器重启的困素
3、 网络故障引起的2节点被驱逐而重启，这个跟上面的分析一样，也是2节点在09:39:59 就关机机了，而1节点在09:40:18 才发现与2节点网络心跳连接不通了，所以也说明此因素不成立
惊喜发现：从NMON信息中发现了一个很有意思的问题，Eth1（心跳网络）正常，2节点的Eth2（对外提供服务的网络）在早上8：00整，流量全部降为0，Memory使用率开始全部释放出来，说明Public网络出问题了，但是没有断线
小结：服务器重启的原因很有可能是人为重启的了
5、验证是否存在人为重启服务器的现象
5.1、查看2节点服务器的历史命令，看是否有重启命令存在
957 init 0 958 su - grid 959 su - oracle 960 su - grid 961 su - grid 962 cd /u01/app/11.2.0/grid/bin 963 ./crsctl start crs 964 su - oracle
分析：在ROOT和户的最后命令里，确实有一条init 0关机命令，在关机命令后，跟着有CRS启动命令
到此，已经确定，服务器是被人为下命令关机的
三、人为关机原因的猜测
1、早上8：00 Public网络出现问题了，用户是无法连接上数据库的
2、早上9：39分，相关人员为了解决这个问题
