记一次生产环境CPU飙高百分之200%的血案

记一次生产环境CPU飙高百分之200%的血案

前言:总是在公众号看别人介绍生产事故,结果风水轮流转今天到我头上。
最近接盘了一个老项目名称不可说,该项目由于经手的人很多代码遗留了很多问题。(/吐槽 举个栗子就跟BakeryOM似的 八代单传老代码 祖传的不可动)此次我负责新增一些功能,一波操作猛如虎后部署上线,当时可能还没人使用系统一切正常。但是下午客户投诉系统不能使用了打开页面都在转圈圈,近半年只有我更新了系统。所以这个雷我踩了,由于线上问题不是小事 我申请完服务器权限后,就开始排查问题。

检查系统内存和CPU的使用情况

  • free工具用来查看系统可用内存:

https://linuxtools-rst.readthedocs.io/zh_CN/latest/tool/free.html

1
2
3
4
[root@iz6ammapnl2v4ez ~]# free
total used free shared buff/cache available
Mem: 1883724 1603884 89592 436 190248 121560
Swap: 0 0 0

Mem指的是内存,Swap指的是交换分区 每一列分别是交换的总量(total),使用量(used)和有多少空闲的交换区(free)。

发现内存一切正常,因为之前服务器内存老不够用,习惯性看一下才放心。

  • top linux下的任务管理器

https://linuxtools-rst.readthedocs.io/zh_CN/latest/tool/top.html

1
2
3
4
5
6
7
8
9
10
[root@iz6ammapnl2v4ez ~]# top
top - 13:43:24 up 24 days, 23:08, 1 user, load average: 0.00, 0.01, 0.05
Tasks: 69 total, 1 running, 68 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.3 us, 0.0 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1883724 total, 84608 free, 1603836 used, 195280 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 121604 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
21605 root 0 -20 128552 8560 5052 S 200 0.5 76:17.81 resin
1 root 20 0 43180 2380 1252 S 0.0 0.1 0:10.70 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd

进程信息

PID:进程的ID
USER:进程所有者
PR:进程的优先级别,越小越优先被执行
NInice:值
VIRT:进程占用的虚拟内存
RES:进程占用的物理内存
SHR:进程使用的共享内存
S:进程的状态。S表示休眠,R表示正在运行,Z表示僵死状态,N表示该进程优先值为负数
%CPU:进程占用CPU的使用率
%MEM:进程使用的物理内存和总内存的百分比
TIME+:该进程启动后占用的总的CPU时间,即占用CPU使用时间的累加值。
COMMAND:进程启动命令名称

通过top命令我发现pid-21605 Resin应用(类似于Tomcat的一种web容器)CPU占用率一直很高而且停不下来。

继续排查问题,由于线上服务器权限太小了 jstack命令无法执行
正常接下来通过top -Hp 21605 命令,可以查看到进程内的线程情况。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
# top -Hp 21605

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
158166 admin 0 -20 5631m 4.0g 102m S 1.0 49.6 31:21.02 java
157051 admin 0 -20 5631m 4.0g 102m S 0.3 49.6 1:56.39 java


# jstack 21605 > /root/jstack.log


找到top -Hp 21605的PID对应的16进制

# printf %x 158166
269d6

# jstack 21605|grep -A 10 269d6

查找到具体线程状态,也可使用dump工具分析问题


注意:
top -Hp命令也可以换成使用 pidstat -p < PID > 1 3 -u -t

紧急下线回滚我的功能,过后发现CPU还是会飙升
沟通后才知道该系统还有一个定时任务,每天定时处理几千个任务,定时暂停后 发现CPU明显下降,仿佛发现了问题。打开页面也正常,自己测试导入一个评论也没问题,这么容易就解决了 当然不能,客户反映当导入一百个时系统就一直等待,查看CPU果然有起飞了。
额o(╥﹏╥)o CPU喝假酒了,有点彪啊

对于cpu飙升这类案件,一般来说有几个对象嫌疑重大:

嫌犯A:内存泄漏,导致大量full GC ——这个没遇到过,不敢瞎bb
嫌犯B:宿主机cpu超卖 ——这个没遇到过,不敢瞎bb
嫌犯C:线程死锁,数据库死锁,代码存在死循环

由于遇到过类似的死锁的问题,我就先查找死锁问题。由于线上服务器权限太小了,只好在本地测试问题。

  • 解释一下什么是死锁?

死锁是指两个或两个以上的进程在执行过程中,由于竞争资源或者由于彼此通信而造成的一种阻塞的现象,若无外力作用,它们都将无法推进下去。此时称系统处于死锁状态或系统产生了死锁,这些永远在互相等待的进程称为死锁进程。(by百度百科)

  • 死锁排查jstack 也可以使用idea的照相机看的当前的进程情况
1
2
3
4
5
6
7
8
9
### 查找进程号
jps -l

### 查看进程
直接查看
jstack -l 12316

导出文件
jstack 12316 > /root/jstack.log

线程的状态:
NEW,未启动的。不会出现在Dump中。
RUNNABLE,在虚拟机内执行的。
BLOCKED,受阻塞并等待监视器锁。
WATING,无限期等待另一个线程执行特定操作。
TIMED_WATING,有时限的等待另一个线程的特定操作。
TERMINATED,已退出的。

搜索一下有没有deadlock,这个就是死锁。发现没有死锁,那就继续查看线程状态。
发现有很多线程都在堵塞或者在执行,没错就是这个的问题,经过同事的帮助下确实发现了那块逻辑死循环跳不出来,不过我想写这个人现在早就高就了~~

  • 由于当时没有留下记录下面图片从网上找了一个,大致差不多会告诉你哪一个方法出现的问题

image

此次不足测试功能时偷懒没有模拟大批量导入的操作,死循环那块代码也没有仔细看,定位问题的时候也没有一下子找到点上,总是忽略一下重要的细节,多次部署上线也没找到问题,耽误了大半天。

正常就应该直接把我的代码切下线来,先排除自己的代码问题(ps:不知道当时咋想的,还是对自己代码不够自信感觉是自己的问题,不够冷静慌个鸡毛 又不是头次遇见生产事故~~)。

image


补充其他神器:

  • 1.Arthas 是Alibaba开源的Java诊断工具,深受开发者喜爱。

https://github.com/alibaba/arthas/blob/master/README_CN.md

  • 2.show-busy-java-threads脚本

https://github.com/oldratlee/useful-scripts

-------------已经触及底线 感谢您的阅读-------------

本文标题:记一次生产环境CPU飙高百分之200%的血案

文章作者:趙小傑~~

发布时间:2019年07月23日 - 22:35:22

最后更新:2019年07月28日 - 00:31:54

原始链接:https://cnsyear.com/posts/5ca61495.html

许可协议: 署名-非商业性使用-禁止演绎 4.0 国际 转载请保留原文链接及作者。

0%