【原創】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 出了問題，可能的本來包括但不限於外設自己故障，磁盤寫滿，掛載的遠程文件系統已經不可訪問等緣由。