情景:测试人员在进行 RabbitMQ 服务器问题排查时,进行了各种重启操作,之后突然发现机器变的很卡。
排查过程:
1. 通过 top 查看,发现名为 sa 的进程 CPU 占用率几乎 100% 。
2. 查看 sa 进程中哪个线程占用 CPU 比较高
[root@rmq_2 ~]# top -Hp 1362
top - 05:36:26 up 2 days, 3:08, 2 users, load average: 1.77, 3.69, 5.11
Tasks: 16 total, 0 running, 16 sleeping, 0 stopped, 0 zombie
Cpu0 : 0.4%us, 2.8%sy, 0.0%ni, 95.7%id, 0.0%wa, 1.1%hi, 0.0%si, 0.0%st
Cpu1 : 0.4%us, 14.7%sy, 0.0%ni, 29.4%id, 53.8%wa, 0.0%hi, 1.8%si, 0.0%st
Cpu2 : 0.7%us, 2.1%sy, 0.0%ni, 95.9%id, 0.0%wa, 0.0%hi, 1.4%si, 0.0%st
Cpu3 : 0.3%us, 5.8%sy, 0.0%ni, 77.1%id, 16.4%wa, 0.0%hi, 0.3%si, 0.0%st
Mem: 3924376k total, 3775972k used, 148404k free, 143432k buffers
Swap: 2097144k total, 688428k used, 1408716k free, 883568k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1532 root 20 0 83964 37m 1196 D 94.7 1.0 127:59.46 MQProducerTask
1497 root 20 0 83964 37m 1196 S 0.3 1.0 3:22.10 OspTimerTask
1362 root 20 0 83964 37m 1196 S 0.0 1.0 0:03.41 sa
1495 root 20 0 83964 37m 1196 S 0.0 1.0 0:42.97 OspLogTask
1496 root 20 0 83964 37m 1196 S 0.0 1.0 0:00.00 OspDispatchTask
1498 root 20 0 83964 37m 1196 S 0.0 1.0 0:00.14 OspTeleDaemon
1499 root 20 0 83964 37m 1196 S 0.0 1.0 0:00.00 OspPostDaemon
1500 root 20 0 83964 37m 1196 S 0.0 1.0 0:05.18 OspNodeMan
1501 root 20 0 83964 37m 1196 S 0.0 1.0 0:06.28 WDClient
1504 root 20 0 83964 37m 1196 S 0.0 1.0 0:00.00 ModuleInst
1505 root 20 0 83964 37m 1196 S 0.0 1.0 0:01.79 LgsInst
1506 root 20 0 83964 37m 1196 S 0.0 1.0 0:19.88 BmcInst
1507 root 20 0 83964 37m 1196 S 0.0 1.0 9:04.17 LogicSrvInst
1508 root 20 0 83964 37m 1196 S 0.0 1.0 0:00.00 FileSend
1531 root 20 0 83964 37m 1196 S 0.0 1.0 0:07.58 MQProducerTask
1533 root 20 0 83964 37m 1196 S 0.0 1.0 0:38.01 MQConsumerTask
从上面的信息中可以发现两点:
- 名字为 MQProducerTask 的线程占用的 CPU 几乎为 100%;
- 名字为 MQProducerTask 的线程的状态为 D ;
3.跟踪 MQProducerTask 线程的执行
[root@rmq_2 guard]# strace -p 1532
Process 1532 attached - interrupt to quit
[ Process PID=1532 runs in 32 bit mode. ]
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
write(2, "[MQ][producer_tag s:52][fsm:conn"..., 75) = -1 ENOSPC (No space left on device)
...
发现该线程一直在向 stderr 输出打印信息,并且已经出现磁盘空间不足的提示信息。
4.确认磁盘情况确实已满
[root@rmq_2 guard]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/VolGroup-LogVol01 195G 195G 0 100% /
tmpfs 1.9G 0 1.9G 0% /dev/shm
/dev/sda1 194M 34M 150M 19% /boot
[root@rmq_2 guard]#
从业务开发了解到,sa 进程为排查问题,会将 stderr 重定向到 log/sa_rabbitmq.log 日志中。经确认, 该文件已经达到 110G+ 。
5.测试人员手动删除 sa_rabbitmq.log 文件,但是问题依然没有得到解决。可以看到磁盘占用仍旧是 100% ,然后查看 log 下的文件,却发现日志大小为 0 。
[root@rmq_2 log]# ll
total 192472
-rw-r--r-- 1 root root 5243673 May 21 15:30 0sa.txt
-rw-r--r-- 1 root root 5243277 May 21 23:44 10sa.txt
-rw-r--r-- 1 root root 5243373 May 22 00:33 11sa.txt
-rw-r--r-- 1 root root 5243704 May 22 01:22 12sa.txt
-rw-r--r-- 1 root root 5243609 May 22 02:28 13sa.txt
-rw-r--r-- 1 root root 4714496 May 22 03:35 14sa.txt
-rw-r--r-- 1 root root 28672 May 22 04:42 15sa.txt
-rw-r--r-- 1 root root 12288 May 22 05:26 16sa.txt
-rw-r--r-- 1 root root 155648 May 22 05:27 17sa.txt
-rw-r--r-- 1 root root 135168 May 22 05:27 18sa.txt
-rw-r--r-- 1 root root 114688 May 22 05:32 19sa.txt
-rw-r--r-- 1 root root 5243431 May 21 16:20 1sa.txt
-rw-r--r-- 1 root root 5243711 May 21 17:09 2sa.txt
-rw-r--r-- 1 root root 5243431 May 21 17:58 3sa.txt
-rw-r--r-- 1 root root 5243278 May 21 18:48 4sa.txt
-rw-r--r-- 1 root root 5243285 May 21 19:37 5sa.txt
-rw-r--r-- 1 root root 5243698 May 21 20:26 6sa.txt
-rw-r--r-- 1 root root 5243573 May 21 21:16 7sa.txt
-rw-r--r-- 1 root root 5243399 May 21 22:05 8sa.txt
-rw-r--r-- 1 root root 5243647 May 21 22:54 9sa.txt
-rw-r--r-- 1 root root 118338715 May 22 01:30 daemon.log
-rw-r--r-- 1 root root 38613 May 22 01:26 saexc.log
-rw-r--r-- 1 root root 7099 May 22 01:26 saexc.log-maps
-rw-r--r-- 1 root root 0 May 22 02:54 sa_rabbitmq.log
-rw-r--r-- 1 root root 16384 May 22 05:46 sa.txt
-rw-r--r-- 1 root root 8019 May 20 02:28 startsrv.log
[root@rmq_2 log]#
查看网上相关资料,结论就是: 磁盘文件虽然被删除,却仍被某进程占用,并且还在写(这个说法其实不准确,因为磁盘已满情况下,是无法写入的)。在这种情况下,通过 du 命令是无法找到占用磁盘的大文件。与此同时,被删除的文件仍然会占用磁盘空间。
6.通过命令确认被删除的文件仍在被进程使用
[root@rmq_2 log]# lsof | grep deleted
sa 1362 root 2w REG 253,0 197264424960 1312057 /opt/mcu/guard/log/sa_rabbitmq.log (deleted)
...
[root@rmq_2 log]#
确实文件被删除了,但仍旧被进程 sa 所占用,解决办法就是把相关的进程进行重启,空间自然就被释放了。
至于上面业务线程狂刷打印问题的原因和解决办法如下:
分析 MQProducerTask 线程狂刷上面的日志信息的原因,是因为 FSM 在 conn_idle 状态收到了非 EV_TIMEOUT 事件。并且代码中没有对这个错误分支做事件相关处理,只是输出打印信息。故代码执行完毕后会重新进入 conn_idle 状态,并沿用前一次的事件,导致死循环。源代码如下
default:
fprintf( stderr, "[MQ][%s s:%d][fsm:conn_idle][*] Weird! NOT Trigger by EV_TIMEOUT\n",
conn->tag, amqp_get_sockfd(conn) );
break;
变更如下
default:
fprintf( stderr, "[MQ][%s s:%d][fsm:conn_idle][*] Weird! NOT Trigger by EV_TIMEOUT, but by %d\n",
conn->tag, amqp_get_sockfd(conn), trigger_ev );
update_event( conn, 0, RET_IMMEDIATELY );
conn_set_state( conn, conn_idle );
stop = 1;
break;
另外,还可以将代码中所有要跳转到 conn_idle 状态,且事件更新 XXX 不为 0 的地方都进行修改,以彻底杜绝其它事件的干扰。
update_event( conn, XXX, RET_IMMEDIATELY );
conn_set_state( conn, conn_idle );
补充:
- 进程状态为 D 表示当前进程正处于 uninterruptible sleep 状态。
- Linux 进程有两种睡眠状态,一种为 interruptible sleep 状态,处在这种状态的进程是可以通过向它发信号来进行唤醒的。比如发 HUP 信号给 nginx 的 master 进程可以让 nginx 重新加载配置文件,而不需要重新启动 nginx 进程;另外一种是 uninterruptible sleep 状态,处在这种状态的进程不接受外来的任何信号,所以也无法通过 kill 进行杀死,要想干掉处在 D 状态进程就只能重启整个 Linux 系统了(具有有些情况下,甚至都无法重启)。
进程为什么会被置于 uninterruptible sleep 状态呢?
处于 uninterruptible sleep 状态的进程通常是在等待 I/O,比如磁盘 I/O,网络 I/O,其他外设 I/O,如果进程正在等待的 I/O 在较长的时间内都没有响应,那么就会很不幸地被 ps 所看到(或者通过 top 看到)。
出现这个状态就意味着很可能有 I/O 出了问题,可能的原本包括但不限于外设本身故障,磁盘写满,挂载的远程文件系统已经不可访问等原因。