一个进程稳定占用CPU 100%问题处理记录

前几个月遇到过这样一个问题:一个业务进程的CPU占用率稳定在99.9x%到100%浮动(16核服务器,CPU满载为1600%),业务代码都是IO密集型的增删改查,没有太多占用CPU的操作,感觉不太正常。由于故障处理第一时间没有记录相关命令的执行结果,只能模拟一下执行相关命令的结果。问题调查过程如下:
1.执行top,按P按照cpu占用率排序,找到该进程,记录进程号pid

top - 21:40:45 up 71 days,  6:12,  4 users,  load average: 0.27, 0.41, 0.48
Tasks: 295 total,   1 running, 294 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.7 us,  0.9 sy,  0.0 ni, 96.1 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
KiB Mem : 65713420 total, 31008160 free, 26820948 used,  7884312 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 37552608 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                   
23140 www-data  20   0 5887912 1.682g  25108 S  99.9  2.7   9:47.99 java                                                                                      
28428 www-data  20   0 5813480 2.457g  24968 S  12.3  3.9 248:32.05 java                                                                                      
56649 www-data  20   0 5739432 2.153g  27568 S   5.0  3.4  80:09.12 java                                                                                      
30202 www-data  20   0 5824892 1.407g  24104 S   3.3  2.2  37:55.28 java                                                                                      
62716 www-data  20   0 5844888 1.574g  24292 S   3.0  2.5   9:22.16 java                                                                                      
63731 www-data  20   0 5820428 2.031g  24752 S   3.0  3.2  60:26.88 java                                                                                      
33209 www-data  20   0 5855216 1.556g  24580 S   2.0  2.5  11:42.94 java                                                                                      
54454 www-data  20   0 6100816 0.992g  18176 S   1.7  1.6 187:26.81 java                                                                                      
60647 www-data  20   0 5712880 1.924g  24884 S   1.7  3.1  27:21.18 java    

假设执行结果如上,占用CPU的进程号为23140
2.执行 sudo -u www-data jstack 23140 > /home/yangyujian/tmp.jstack 打印该进程的jstack信息
3.执行 ps -mp 23140 -o THREAD,tid,time 打印进程23140的线程列表以及占用CPU的时间等信息,模拟执行结果如下

USER     %CPU PRI SCNT WCHAN  USER SYSTEM   TID     TIME
www-data 99.9   -    - -         -      -     - 01:10:17
www-data  0.0  19    - -         -      - 23140 00:00:00
www-data  99.9  19    - -         -      - 23142 01:10:17
www-data  0.0  19    - -         -      - 23143 00:00:01
www-data  0.0  19    - -         -      - 23144 00:00:01
www-data  0.0  19    - -         -      - 23145 00:00:01
www-data  0.0  19    - -         -      - 23146 00:00:01
www-data  0.0  19    - -         -      - 23147 00:00:01
www-data  0.0  19    - -         -      - 23148 00:00:01

可以看到占用CPU最高的线程id为23142
4.将线程id: 23142 转为16进制: 5a66,在jstack信息中寻找该线程id,即可找到堆栈信息。

最终发现是公司内部封装的RPC框架内一个失败重连的机制导致死循环,所以稳定占用一个核,联系框架维护者修复解决。

Author: rainj2013
Link: https://rainj2013.top/2018/09/11/一个CPU占用稳定100-问题处理记录/
Copyright Notice: All articles in this blog are licensed under CC BY-NC-SA 4.0 unless stating additionally.