【原创】CPU 100%+磁盘写满 问题排查

情景：测试人员在进行 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 出了问题，可能的本来包括但不限于外设自己故障，磁盘写满，挂载的远程文件系统已经不可访问等缘由。