1、故障描述
今天下午,cell10存储节点莫名其妙地自动重启了。虽然数据库没有受到影响,但仍然需要弄清楚重启的原因。以下记录整个故障的分析过程。
2、故障分析
2.1 分析操作系统日志。故障前后的操作系统日志摘要如下所示。
Jan 4 09:25:29 dm01celadm10 auditd[12291]: Audit daemon rotating log files Jan 4 12:10:39 dm01celadm10 auditd[12291]: Audit daemon rotating log files Jan 4 14:05:07 dm01celadm10 kernel: imklog 5.8.10, log source = /proc/kmsg started. Jan 4 14:05:07 dm01celadm10 rsyslogd: [origin software="rsyslogd" swVersion="5.8.10" x-pid="12364" x-info="http://www.rsyslog.com"] start Jan 4 14:05:07 dm01celadm10 kernel: [ 0.000000] Initializing cgroup subsys cpuset Jan 4 14:05:07 dm01celadm10 kernel: [ 0.000000] Initializing cgroup subsys cpu Jan 4 14:05:07 dm01celadm10 kernel: [ 0.000000] Initializing cgroup subsys cpuacct Jan 4 14:05:07 dm01celadm10 kernel: [ 0.000000] Linux version 4.1.12-94.8.4.el6uek.x86_64 (mockbuild@x86-ol6-builder-04) (gcc version 4.9.2 20150212 (Red Hat 4.9.2-6.2.0.3) (GCC) ) #2 SMP Sat May 5 16:14:51 PDT 2018 Jan 4 14:05:07 dm01celadm10 kernel: [ 0.000000] Command line: root=/dev/md5 bootarea=c0d0 bootfrom=CELLBOOT ro loglevel=7 panic=60 debug pci=noaer log_buf_len=1m nmi_watchdog=0 transparent_hugepage=never rd_NO_PLYMOUTH crashkernel=448M@128M audit=1 console=tty1 console=ttyS0,115200n8 numa=off |
从操作系统的message日志可以看出,14:05分是操作系统启动后的日志,这说明操作系统的关闭时间是在14:05之前的几分钟。而重启之前 ,操作系统没有任何的故障日志产生。
2.2 分析ILOM日志。查看@usr@local@bin@fmadm_faulty_-av.out日志文件,显示为:No faults found, 这说明该存储节点不存在硬件故障。
2.3 检查存储管理软件的日志。list alerthistory命令输出显示:
2025-01-04T14:01:38+08:00 critical "Read-only file system detection thread was hung. Cell was power cycled to stop the hang." |
从存储管理软件的日志可以看出,在14:01分,存储管理软件检测到线程出现了hung的情况,为了避免出现hung而导致整个存储集群不可用,存储管理软件主动地重启了该存储节点。
至此,我们已经清楚了该存储节点重启的原因:存储管理软件检测到线程出现了hung的情况。 为什么会出现hung的情况? 是操作系统的资源使用紧张?
2.4 通过Exawatcher工具,分析该存储节点出现故障时间段的资源使用情况。发现在出现故障之前,该存储节点的CPU,内存,IO都非常空闲。
zzz <01/04/2025 13:59:48> Count:611
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 0 47450364 482896 7459500 0 0 2203 794 0 0 2 2 97 0 0
1 0 0 47448424 482896 7459724 0 0 35617 16122 34701 70589 2 1 97 0 0
zzz <01/04/2025 13:59:53> Count:612
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
2 0 0 47448424 482896 7459724 0 0 2203 794 0 0 2 2 97 0 0
01/04/2025 01:58:34 PM
avg-cpu: %user %nice %system %iowait %steal %idle
1.68 0.15 3.22 0.00 0.00 94.95
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sdd 0.00 0.00 0.60 20.20 8.00 73.80 3.93 0.05 2.18 72.67 0.09 2.15 4.48
sdg 0.00 0.00 1.00 68.00 12.80 146.80 2.31 0.01 0.20 9.60 0.06 0.18 1.22
sdc 0.00 0.00 0.40 21.80 4.80 226.40 10.41 0.00 0.15 7.00 0.03 0.15 0.34
sdi 0.60 0.20 0.80 5.60 414.40 1230.40 257.00 0.01 1.41 10.50 0.11 1.37 0.88
sdh 0.00 0.00 0.40 297.80 6.40 650.00 2.20 0.04 0.14 24.00 0.11 0.06 1.66
sdj 0.00 0.00 0.60 290.40 8.00 1662.40 5.74 0.16 0.55 31.67 0.48 0.10 2.78
sdl 0.00 0.00 0.80 15.20 11.20 121.60 8.30 0.01 0.68 12.50 0.05 0.68 1.08
sdk 0.00 0.00 0.80 1.20 12.80 9.60 11.20 0.01 3.80 9.50 0.00 3.80 0.76
sdm 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdm1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda 0.00 13.40 0.80 106.80 9.60 400.60 3.81 0.01 0.14 13.25 0.04 0.14 1.46
sda1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda3 0.00 0.00 0.80 102.20 9.60 239.00 2.41 0.01 0.14 13.25 0.04 0.14 1.46
sda4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda5 0.00 11.40 0.00 3.00 0.00 132.80 44.27 0.00 0.00 0.00 0.00 0.00 0.00
sda6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda7 0.00 0.60 0.00 0.80 0.00 11.20 14.00 0.00 0.00 0.00 0.00 0.00 0.00
sda8 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda9 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda10 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sda11 0.00 1.40 0.00 0.80 0.00 17.60 22.00 0.00 0.00 0.00 0.00 0.00 0.00
md2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md8 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md7 0.00 0.00 0.00 1.00 0.00 8.00 8.00 0.00 0.00 0.00 0.00 0.00 0.00
md11 0.00 0.00 0.00 1.80 0.00 14.40 8.00 0.00 0.00 0.00 0.00 0.00 0.00
md1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
md5 0.00 0.00 0.00 13.60 0.00 126.40 9.29 0.00 0.00 0.00 0.00 0.00 0.00
md4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
nvme0n1 0.00 0.00 209.20 314.40 10248.00 8078.40 35.00 0.05 0.10 0.18 0.04 0.07 3.86
nvme1n1 0.00 0.00 269.40 423.40 25092.40 8325.00 48.24 0.07 0.10 0.16 0.06 0.08 5.58
nvme2n1 0.00 0.00 797.80 751.00 72078.00 14998.20 56.22 0.25 0.16 0.23 0.09 0.08 12.84
nvme3n1 0.00 0.00 350.20 385.20 12614.40 5877.80 25.15 0.07 0.09 0.15 0.03 0.07 5.20
sde 0.00 0.40 10.80 317.00 24.20 713.40 2.25 0.17 0.53 12.15 0.14 0.35 11.44
sdn 0.00 13.60 10.80 655.80 19.80 4100.80 6.18 0.14 0.21 8.11 0.08 0.15 10.14
sdn1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn3 0.00 0.20 10.80 651.20 19.80 3939.20 5.98 0.14 0.21 8.11 0.08 0.15 10.12
sdn4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn5 0.00 11.40 0.00 3.00 0.00 132.80 44.27 0.00 0.00 0.00 0.00 0.00 0.00
sdn6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn7 0.00 0.60 0.00 0.80 0.00 11.20 14.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn8 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn9 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn10 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdn11 0.00 1.40 0.00 0.80 0.00 17.60 22.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 0.80 0.20 12.80 1.60 14.40 0.01 7.40 9.25 0.00 7.40 0.74
从Exawatcher日志可以看出,在出现故障之前,系统资源使用率非常低,这说明不是由于操作系统资源使用过载导致存储软件hung。
2.5 怀疑该故障是存储软件的BUG所致。搜索MOS,找到了《Read-only file system detection thread was hung. Cell was power cycled to stop the hang (Doc ID 2296267.1)》,该文章中所提及的故障现象与上述分析过程中查看到的现象完全一致。除此之外,文章中还提及RAID卡的固件日志,在主机重启前几分钟固件会崩溃,并且RAID HBA 重置。
2.6 检查RAID卡的固件日志。日志如下:
01/04/25 13:47:51: C0:Max Temperature = 77 on Channel 1
Firmware crash dump feature enabled
Crash dump collection will start immediately
copied 75 MB in 202980 Microseconds
[0]: fp=c02da8d8, lr=c13244d0 - _MonTask+200
[1]: fp=c02daa00, lr=c1378c84 - mfiIdrIsr+19c
[2]: fp=c02daa18, lr=c03e1374 - external_IRQ+58
[3]: fp=c02daa20, lr=c03e0074 - _External_IRQ+74
[4]: fp=c02daa70, lr=c03495f8 - raid_task_idle_loop+24
[5]: fp=c02daa80, lr=c123b388 - raid_task+7cc
[6]: fp=c02dabe0, lr=c1381d40 - _main+1100
[7]: fp=c02dac00, lr=fc80299c - __start+1944
MonTask: line 1222 in file ../../raid/1078dma.c
果然,在13:47分,也即主机重启前的15分钟,RAID卡的固件Crash。
3。至此,整个故障已经非常清楚。是由于存储管理软件的bug(26499981),导致主机重启。需要升级存储管理软件至18.1或更高的版本才能修复该BUG。