JVM 技术详解:JVM 问题排查分析下篇(案例实战)

GC 问题排查实战案例

这一部分,我们来看一个实际的案例。

假设我们有一个提供高并发请求的服务,系统使用 Spring Boot 框架,指标采集使用 MicroMeter,监控数据上报给 Datadog 服务。

当然,Micrometer支 持将数据上报给各种监控系统,例如:AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometh eus、SignalFx、Stackdriver、StatsD、Wavefront 等等。

有关MicroMeter的信息可参考:

https://micrometer.io/docs

问题现象描述

最近一段时间,通过监控指标发现,有一个服务节点的最大 GC 暂停时间经常会达到 400ms 以上。

如下图所示:

85083641.png

从图中可以看到,GC 暂停时间的峰值达到了 546ms,这里展示的时间点是 2020 年 02 月 04 日 09:20:00 左右。

客户表示这种情况必须解决,因为服务调用的超时时间为 1s,要求最大 GC 暂停时间不超过 200ms,平均暂停时间达到 100ms 以内,对客户的交易策略产生了极大的影响。

CPU 负载

CPU 的使用情况如下图所示:

58517646.png

从图中可以看到:系统负载为 4.92,CPU使用率 7% 左右,其实这个图中隐含了一些重要的线索,但我们此时并没有发现什么问题。

GC 内存使用情况

然后我们排查了这段时间的内存使用情况:

85674124.png

从图中可以看到,大约 09:25 左右 old_gen 使用量大幅下跌,确实是发生了 FullGC。

但 09:20 前后,老年代空间的使用量在缓慢上升,并没有下降,也就是说引发最大暂停时间的这个点并没有发生 FullGC。

当然,这些是事后复盘分析得出的结论。当时对监控所反馈的信息并不是特别信任,怀疑就是触发了 FullGC 导致的长时间 GC 暂停。

为什么有怀疑呢,因为 Datadog 这个监控系统,默认 10s 上报一次数据。有可能在这 10s 内发生些什么事情但是被漏报了(当然,这是不可能的,如果上报失败会在日志系统中打印相关的错误)。

再分析上面这个图,可以看到老年代对应的内存池是 "ps_old_gen",通过前面的学习,我们知道,ps 代表的是 ParallelGC 垃圾收集器。

JVM 启动参数

查看 JVM 的启动参数,发现是这样的:

-Xmx4g -Xms4g

我们使用的是 JDK 8,启动参数中没有指定 GC,确定这个服务使用了默认的并行垃圾收集器。

于是怀疑问题出在这款垃圾收集器上面,因为很多情况下 ParallelGC 为了最大的系统处理能力,即吞吐量,而牺牲掉了单次的暂停时间,导致暂停时间会比较长。

使用 G1 垃圾收集器

怎么办呢?准备换成 G1,毕竟现在新版本的 JDK 8 中 G1 很稳定,而且性能不错。

然后换成了下面的启动参数:

# 这个参数有问题,启动失败
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMills=50ms

结果启动失败,忙中出错,参数名和参数值都写错了。

修正如下:

-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50

接着服务启动成功,等待健康检测自动切换为新的服务节点,继续查看指标。

55932616.png

看看暂停时间,每个节点的 GC 暂停时间都降下来了,基本上在 50ms 以内,比较符合我们的预期。

嗯!事情到此结束了?远远没有。

“彩蛋”惊喜

过了一段时间,我们发现了个下面这个惊喜(也许是惊吓),如下图所示:

50244521.png

中奖了,运行一段时间后,最大 GC 暂停时间达到了 1300ms。

情况似乎更恶劣了。

继续观察,发现不是个别现象:

84108207.png

内心是懵的,觉得可能是指标算错了,比如把 10s 内的暂停时间全部加到了一起。

注册 GC 事件监听

于是想了个办法,通过 JMX 注册 GC 事件监听,把相关的信息直接打印出来。

关键代码如下所示:

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

推荐阅读更多精彩内容