情景：测试人员在进行 RabbitMQ 服务器问题排查时，进行了各种重启操作，之后突然发现机器变的很卡。
排查过程：
1.通过 top 查看，发现名为 sa 的进程 CPU 占用率几乎 100% 。
2.查看 sa 进程中哪个线程占用 CPU 比较高
从上面的信息中可以发现两点：
发现该线程一直在向 stderr 输出打印信息，并且已经出现磁盘空间不足的提示信息。
4.确认磁盘情况确实已满
从业务开发了解到，sa 进程为排查问题，会将 stderr 重定向到 log/sa_rabbitmq.log 日志中。经确认，
该文件已经达到 110G+ 。
5.测试人员手动删除 sa_rabbitmq.log 文件，但是问题依然没有得到解决。可以看到磁盘占用仍旧是 100% ，然后查看 log 下的文件，却发现日志大小为 0 。
查看网上相关资料，结论就是：
有文件虽然被删除，却仍被某进程占用，并且还在写（这个说法其实不准确，因为磁盘满的情况下，是无法写入的）。
在这种情况下，通过 du 命令是无法找到占用磁盘的大文件。与此同时，被删除的文件仍然会占用磁盘空间。
6.通过命令确认被删除的文件仍在被进程使用
确实文件被删除了，但仍旧被进程 sa 所占用，解决办法就是把相关的进程进行重启，空间自然就被释放了。
至于上面业务线程狂刷打印问题的原因和解决办法如下：
分析 MQProducerTask 线程狂刷上面的日志信息的原因，是因为 FSM 在 conn_idle 状态收到了非 EV_TIMEOUT 事件。并且代码中没有对这个错误分支做事件相关处理，只是输出打印信息。故代码执行完毕后会重新进入 conn_idle 状态，并沿用前一次的事件，导致死循环。源代码如下
变更如下
另外，还可以将代码中所有要跳转到 conn_idle 状态，且事件更新 XXX 不为 0 的地方都进行修改，以彻底杜绝其它事件的干扰。
补充：
进程为什么会被置于 uninterruptible sleep 状态呢？
处于 uninterruptible sleep 状态的进程通常是在等待 I/O，比如磁盘 I/O，网络 I/O，其他外设 I/O，如果进程正在等待的 I/O 在较长的时间内都没有响应，那么就会很不幸地被 ps 所看到（或者通过 top 看到）。
出现这个状态就意味着很可能有 I/O 出了问题，可能的原本包括但不限于外设本身故障，磁盘写满，挂载的远程文件系统已经不可访问等原因。
排查过程：
1.通过 top 查看，发现名为 sa 的进程 CPU 占用率几乎 100% 。
2.查看 sa 进程中哪个线程占用 CPU 比较高
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
|
[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 ；
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
|
[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)
...
|
4.确认磁盘情况确实已满
|
1
2
3
4
5
6
|
[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]
#
|
5.测试人员手动删除 sa_rabbitmq.log 文件，但是问题依然没有得到解决。可以看到磁盘占用仍旧是 100% ，然后查看 log 下的文件，却发现日志大小为 0 。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
|
[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.通过命令确认被删除的文件仍在被进程使用
|
1
2
3
4
|
[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]
#
|
至于上面业务线程狂刷打印问题的原因和解决办法如下：
分析 MQProducerTask 线程狂刷上面的日志信息的原因，是因为 FSM 在 conn_idle 状态收到了非 EV_TIMEOUT 事件。并且代码中没有对这个错误分支做事件相关处理，只是输出打印信息。故代码执行完毕后会重新进入 conn_idle 状态，并沿用前一次的事件，导致死循环。源代码如下
|
1
2
3
4
|
default
:
fprintf
( stderr,
"[MQ][%s s:%d][fsm:conn_idle][*] Weird! NOT Trigger by EV_TIMEOUT\n"
,
conn->tag, amqp_get_sockfd(conn) );
break
;
|
|
1
2
3
4
5
6
7
8
|
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
;
|
|
1
2
|
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 出了问题，可能的原本包括但不限于外设本身故障，磁盘写满，挂载的远程文件系统已经不可访问等原因。
