记一次CPU与内存飙高的线上事故

背景介绍

我负责一个物联网平台的开发与运维工作,2020年12月18日的一天,恰逢周五,本来以为可以划划水就可以过愉快的周末了,一大早让我看下昨天的设备上报的数据情况,打开浏览器输入网址,无法正常登录,提示服务器内部错误!我心里一想不对呀,本人照看的系统已经稳定运行很长一段时间了,怎么会这样?都坐下,不要慌,我们慢慢的来处理。

处理过程

首先,通过我的FinalShell工具通过ssh登录服务器,一眼就看到了让我震惊的结果,我开始慌了。。。

有个java进程居然内存和CPU占用都这么高,然后我简单看了一下进程号,定位到是物联网平台的后台服务进程(由于该平台是采用docker部署的,因此需要进入docker容器内部进行查看)

https://upload-images.jianshu.io/upload_images/19453215-ad97595918967d4d.png
docker exec -it cfe1916c608a /bin/bash

通过docker exec进入容器内部,首先还是使用我们比较常用top看下情况

https://upload-images.jianshu.io/upload_images/19453215-7f9790cc733d322e.png

果然,与我们看到的现象一致,有个java进程RES占有高达8.6g,%CPU高达277.0,这时突然有些兴奋呀,我又可以躺坑了,事后会被作为经验文章分享出来,也就是你现在看到的样子😂。然后我们一步步来分析和处理。。。

接下来,我们主要从CPU升高的方向先入手分析。复制该进程的id号8,通过执行top -Hp查看当前进程的各个线程执行情况

top -Hp 8
https://upload-images.jianshu.io/upload_images/19453215-89789eb963c20dd3.png

可以看到,前面几个线程的CPU占用都非常高,我们随机挑选一个PID为13的线程进行分析,需要注意的是,在jstack命令展示中,线程id都是转化成的十六进制形式,使用以下命令打印线程id的16进制结果

https://upload-images.jianshu.io/upload_images/19453215-5f78d8f2be21c421.png

重点来了,执行jstack查看堆栈信息情况

jstack 8 |grep d
https://upload-images.jianshu.io/upload_images/19453215-efe9db4efe6a7ffc.png

终于发现因为什么导致CPU升高了,可以看到a,b,c,d都是代表GC线程(PS:上图中的10~13这几个都是GC线程),我们大概猜测应该就是因为GC进行频繁的垃圾回收,导致其他业务无法正常的工作。好的,我们还是通过jstat验证一下

jstat -gcutil 8 2000 10 
https://upload-images.jianshu.io/upload_images/19453215-d6642efef381cc11.png

果然,这个FGC与FGCT显示的fullGC的次数和时间是不是让你头皮发麻 😫。然后,给大家一个小技巧,我们先通过jmap -histo命令先大致查看下堆内存的对象数量和大小情况

jmap -histo:live 8 | more
https://upload-images.jianshu.io/upload_images/19453215-3f322633bdfa3ef1.png

从分析中我们可以看到【B与【C占有都非常高,这是什么玩意?其实这个Byte和Char数组,大胆猜测可能是有大量的String字符串。。。

class name是对象类型,说明如下:

  • B byte
  • C char
  • D double
  • F float
  • I int
  • J long
  • Z boolean
  • [ 数组,如[I表示int[]
  • [L+类名 其他对象

我们还是来好好分析下,到底是什么原因导致的GC经过这么努力在释放堆内存还是释放不出来,帮帮JVM虚拟机诊断下病因,这个时候其实大家应该已经知道我们应该看下堆内存里面到底是什么

首先,我们通过jmap -dump导出现在JVM的堆内存日志情况

jmap -dump:format=b,file=dump.dat 8
https://upload-images.jianshu.io/upload_images/19453215-518353238562a5c9.png

然后,从服务器下载dump.dat文件到本机,通过Eclipse Memory Analyzer工具对其进行分析查看

内存使用整体情况

https://upload-images.jianshu.io/upload_images/19453215-97991c5e7f592d62.png

直接点击下方Reports→Leak Suspects链接来生成报告,查看导致内存泄露的罪魁祸首

https://upload-images.jianshu.io/upload_images/19453215-7a84e7bb8c8f9c05.png

从图中可以看出一个可疑对象消耗了近93.43%的内存。接着往下看,点击Details查看详细情况

https://upload-images.jianshu.io/upload_images/19453215-66e9da2f19a9badb.png

备注:

Shallow Heap 为对象自身占用的内存大小,不包括它引用的对象。

Retained Heap 为当前对象大小 + 当前对象可直接或间接引用到的对象的大小总和

点击dominator_tree查看entries heap对象引用关系tree进行分析

https://upload-images.jianshu.io/upload_images/19453215-94e015c3931ffa11.png

最终通过点击entries引用tree层层查看对象的引用情况,查看熟悉的东西,定位到好像与device_log_mtu_2020-12这个地方有关系

https://upload-images.jianshu.io/upload_images/19453215-3ec62b7110533621.png

其实我们已经大概定位到问题出现位置了,接下来其实就要结合业务系统情况来追查业务情况与分析系统代码,最终定位到问题的原因:

以下截图是我与系统的技术开发人员的交流,最终大概定位到问题的原因:因为代码的逻辑bug导致出现死循环

https://upload-images.jianshu.io/upload_images/19453215-f9f303b2b939e86c.png

总结

先通过top命令查看CPU与内存情况,查看是什么进程的CPU和内存飙高,如果是CPU比较高,则可以通过top -Hp <pid>命令查看当前进程的各个线程运行情况,找出CPU过高的线程以后,将其线程id转换为十六进制的形式后,然后通过jstack日志查看改线程的工作状态和调用栈情况,这里有两种情况:

  1. 如果是正常的用户线程,则通过该线程的堆栈信息查看其具体在哪出代码运行比较消耗CPU;
  2. 如果该线程是VM Thread,则通过jstat -gcutil <pid> <period> <times>命令监控当前系统的GC状况,然后通过jmap dump:format=b,file=<filepath> <pid>导出系统当前的内存数据。导出之后将内存情况放到eclipse的mat工具中进行分析即可得出内存中主要是什么对象比较消耗内存,进而可以处理相关代码

如果企业内部本身没有相关监控与运维工具,那我们可以使用JDK本身提供了一些监控分析工具(jps、jstack、jmap、jhat、jstat、hprof等),通过灵活运用这些工具几乎能够定位Java项目80%的性能问题。最后在这里推荐一个Alibaba开源的Java诊断工具Arthas可以帮助你解决:

  1. 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
  2. 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
  3. 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
  4. 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
  5. 是否有一个全局视角来查看系统的运行状况?
  6. 有什么办法可以监控到JVM的实时运行状态?
  7. 怎么快速定位应用的热点,生成火焰图?

参考资料

系统运行缓慢,CPU 100%,以及Full GC次数过多问题的排查思路

JVM性能调优监控工具jps、jstack、jmap、jhat、jstat、hprof_憧憬的专栏-CSDN博客

本文由博客一文多发平台 OpenWrite 发布!

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 159,117评论 4 362
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,328评论 1 293
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 108,839评论 0 243
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,007评论 0 206
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,384评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,629评论 1 219
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,880评论 2 313
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,593评论 0 198
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,313评论 1 243
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,575评论 2 246
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,066评论 1 260
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,392评论 2 253
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,052评论 3 236
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,082评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,844评论 0 195
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,662评论 2 274
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,575评论 2 270

推荐阅读更多精彩内容