某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分，相关人员为了解决这个问题，就把服务器给关机了

3、服务器关机到重启，总共花费了 5 分钟

4、为了验证管理人员在验证网络的问题，看看1节点的最近历史命令，发现有人在1节点上在做ping 2节点的网络测试呢

  929  cat /etc/hosts

  930  ping 10.X.XX.80

  931  ping 10.X.XX.81

  932  ping 10.X.XX.82

  933  ping 10.X.XX.83

  934  su - oracle

  935  cd /home/

  936  ls

  937  su - grid

  938  ssh 10.1.146.33

  939  top

  940  free -m

  941  su - grid

  942  vmstat 1 01

  943  vmstat 1 10

  944  su - grid

  945  su - grid

  946  su - oracle

  947  su - oracle

  948  su - grid

  949  su - oracle

  950  su - grid

  951  cat /etc/hosts

  952  ping 10.X.XX.81

  953  ping 10.X.XX.83

 

 本文已经过经信息“脱敏”，将在子衿优化团队官方论坛上同步发表，地址为： http://dba.oraclefans.cn/discuz/forum.php?mod=viewthread&tid=1263&fromuid=21

本文作者：黎俊杰（网名：踩点），从事”系统架构、操作系统、存储设备、数据库、中间件、应用程序“六个层面系统性的性能优化工作

欢迎加入系统性能优化专业群，共同探讨性能优化技术。群号：258187244