【原创】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 出了问题,可能的原本包括但不限于外设本身故障,磁盘写满,挂载的远程文件系统已经不可访问等原因。

 

 

 

 

 

转载于:https://my.oschina.net/moooofly/blog/418710

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值