JVM GC诡异问题排查,k8s差点害死我……

JAVA日知录 2025-07-01 09:45:59

前言

 

本文将通过一个真实的生产环境案例,详细展示如何系统性地排查和解决JVM垃圾收集问题。这个案例涵盖了从问题发现、分析诊断到最终解决的完整过程,对于理解JVM调优实战具有重要的参考价值。

 

系统背景

 

我们的服务是一个高并发的微服务应用,技术栈如下:

 

  • 应用框架:Spring Boot

  • 指标采集:Micrometer

  • 监控系统:Datadog

 

说明:Micrometer 作为应用监控的门面库,支持多种监控系统,包括:AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometheus、SignalFx、Stackdriver、StatsD、Wavefront 等。

 

详细信息请参考:https://micrometer.io/docs

 

问题现象

 

问题描述

 

在日常监控中,我们发现一个服务节点出现了严重的GC性能问题:

 

  • 最大GC暂停时间:经常超过400ms

  • 峰值暂停时间:达到546ms(发生时间:02月04日 09:20:00)

 

GC暂停时间监控图

 

业务影响

 

这种GC暂停时间严重影响了业务运行:

 

  • 服务超时:服务调用超时时间为1秒,GC暂停过长导致超时风险

 

  • 性能要求:

最大GC暂停时间 < 200ms

平均暂停时间 < 100ms

 

  • 业务冲击:对客户的交易策略产生了严重影响,亟需解决

 

问题排查过程

 

第一步:系统资源使用分析

 

CPU负载分析

 

首先检查CPU使用情况,监控数据如下:

 

CPU负载监控图

 

观察结果:

系统负载:4.92

CPU使用率:约7%

 

重要提示:这个监控图中实际隐含了重要线索(CPU核心数与GC线程数的不匹配),但当时并未察觉异常。

 

GC 内存使用情况

 

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

 

 

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

 

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

 

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

 

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

 

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

 

第三步:JVM配置分析

 

启动参数检查

 

检查JVM启动参数配置:

 

  •  
-Xmx4g -Xms4g

 

配置分析:

 

  • JDK版本:JDK 8

  • GC选择:未指定,使用默认的ParallelGC

  • 堆内存最大和初始堆内存均为4GB

 

初步问题假设

 

怀疑点:ParallelGC可能是问题根源

 

  • 设计目标:ParallelGC主要追求系统最大吞吐量

  • 权衡策略:为了吞吐量优化,会牺牲单次GC的暂停时间

  • 推测结论:可能因此导致暂停时间过长

 

第一次优化尝试:切换到G1GC

 

优化策略选择

 

选择G1垃圾收集器的理由:

 

稳定性:在JDK 8的新版本中,G1已经相当稳定

性能表现:具有良好的延迟控制能力

适用场景:更适合低延迟要求的应用

 

配置过程

 

初次配置(失败)

 

  •  
  •  
# 参数配置错误,导致启动失败-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMills=50ms

 

错误分析:

 

  • 参数名拼写错误:MaxGCPauseMills → MaxGCPauseMillis

  • 参数值格式错误:50ms → 50

 

修正后配置

 

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

 

初步效果验证

 

服务启动成功,通过健康检测切换到新节点后,监控显示:

 

G1GC初期效果监控图

 

效果评估:

 

  • GC暂停时间:基本控制在50ms以内

  • 符合预期:达到了初期的优化目标

 

但是,问题远未结束.....

 

“彩蛋”惊喜

 

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

 

 

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

 

情况似乎更恶劣了。

 

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

 

 

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

 

注册 GC 事件监听

 

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

 

关键代码如下所示:

 

  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
// 每个内存池都注册监听for (GarbageCollectorMXBean mbean      : ManagementFactory.getGarbageCollectorMXBeans()) {    if (!(mbean instanceof NotificationEmitter)) {        continue// 假如不支持监听...    }    final NotificationEmitter emitter = (NotificationEmitter) mbean;    // 添加监听    final NotificationListener listener = getNewListener(mbean);    emitter.addNotificationListener(listener, nullnull);}

 

通过这种方式,我们可以在程序中监听 GC 事件,并将相关信息汇总或者输出到日志。

 

再启动一次,运行一段时间后,看到下面这样的日志信息:

 

  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
{"duration":1869,"maxPauseMillis":1869,"promotedBytes":"139MB","gcCause":"G1 Evacuation Pause","collectionTime":27281,"gcAction":"end of minor GC","afterUsage": {"G1 Old Gen":"1745MB","Code Cache":"53MB","G1 Survivor Space":"254MB","Compressed Class Space":"9MB","Metaspace":"81MB","G1 Eden Space":"0" },"gcId":326,"collectionCount":326,"gcName":"G1 Young Generation","type":"jvm.gc.pause"}

 

情况确实有点不妙。

 

这次实锤了,不是 FullGC,而是年轻代 GC,而且暂停时间达到了 1869ms。 一点道理都不讲,我认为这种情况不合理,而且观察 CPU 使用量也不高。

 

找了一大堆资料,试图证明这个 1869ms 不是暂停时间,而只是 GC 事件的结束时间减去开始时间。

 

打印 GC 日志

 

既然这些手段不靠谱,那就只有祭出我们的终极手段:打印 GC 日志。

 

修改启动参数如下:

 

  •  
  •  
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50 -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

 

重新启动,希望这次能排查出问题的原因。

 

 

运行一段时间,又发现了超长的暂停时间。

 

分析 GC 日志

 

因为不涉及敏感数据,那么我们把 GC 日志下载到本地进行分析。

 

定位到这次暂停时间超长的 GC 事件,关键的信息如下所示:

 

  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
  •  
Java HotSpot(TM64-Bit Server VM (25.162-b12) for linux-amd64 JRE (1.8.0_162-b12), built on Dec 19 2017 21:15:48 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)Memory: 4k page, physical 144145548k(58207948k free), swap 0k(0k free)CommandLine flags:  -XX:InitialHeapSize=4294967296 -XX:MaxGCPauseMillis=50 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 2020-02-24T18:02:31.853+0800: 2411.124: [GC pause (G1 Evacuation Pause) (young), 1.8683418 secs]   [Parallel Time1861.0 ms, GC Workers48]      [GC Worker Start (ms): Min2411124.3Avg2411125.4Max2411126.2Diff1.9]      [Ext Root Scanning (ms): Min0.0Avg0.3Max2.7Diff2.7Sum16.8]      [Update RS (ms): Min0.0Avg3.6Max6.8Diff6.8Sum172.9]         [Processed BuffersMin0Avg2.3Max8Diff8Sum111]      [Scan RS (ms): Min0.0Avg0.2Max0.5Diff0.5Sum7.7]      [Code Root Scanning (ms): Min0.0Avg0.0Max0.1Diff0.1Sum0.3]      [Object Copy (ms): Min1851.6Avg1854.6Max1857.4Diff5.8Sum89020.4]      [Termination (ms): Min0.0Avg0.0Max0.0Diff0.0Sum0.6]         [Termination AttemptsMin1Avg1.0Max1Diff0Sum48]      [GC Worker Other (ms): Min0.0Avg0.3Max0.7Diff0.6Sum14.7]      [GC Worker Total (ms): Min1858.0Avg1859.0Max1860.3Diff2.3Sum89233.3]      [GC Worker End (ms): Min2412984.1Avg2412984.4Max2412984.6Diff0.5]   [Code Root Fixup0.0 ms]   [Code Root Purge0.0 ms]   [Clear CT1.5 ms]   [Other5.8 ms]      [Choose CSet0.0 ms]      [Ref Proc1.7 ms]      [Ref Enq0.0 ms]      [Redirty Cards1.1 ms]      [Humongous Register0.1 ms]      [Humongous Reclaim0.0 ms]      [Free CSet2.3 ms]   [Eden2024.0M(2024.0M)->0.0B(2048.0K)     Survivors2048.0K->254.0M     Heap3633.6M(4096.0M)->1999.3M(4096.0M)] [Times: user=1.67 sys=14.00, real=1.87 secs] 

 

前后的 GC 事件都很正常,也没发现 FullGC 或者并发标记周期,但找到了几个可疑的点。

 

  • physical 144145548k(58207948k free):JVM 启动时,物理内存 137GB,空闲内存 55GB。

  • [Parallel Time: 1861.0 ms, GC Workers: 48]:垃圾收集器工作线程 48 个。

 

 GC 日志中揭露了几个关键信息,

 

  • user=1.67:用户线程耗时 1.67s;

  • sys=14.00:系统调用和系统等待时间 14s;

  • real=1.87 secs:实际暂停时间 1.87s;

  • GC 之前,年轻代使用量 2GB,堆内存使用量 3.6GB,存活区 2MB,可推断出老年代使用量 1.6GB;

  • GC 之后,年轻代使用量为 0,堆内存使用量 2GB,存活区 254MB,那么老年代大约 1.8GB,那么“内存提升量为 200MB 左右”。

 

这样分析之后,可以得出结论:

 

  • 年轻代转移暂停,复制了 400MB 左右的对象,却消耗了 1.8s,系统调用和系统等待的时间达到了 14s。

  • JVM 看到的物理内存 137GB。

  • 推算出 JVM 看到的 CPU 内核数量 72个,因为 GC 工作线程 72* 5/8 ~= 48 个。

 

看到这么多的 GC 工作线程我就开始警惕了,毕竟堆内存才指定了 4GB。

 

按照一般的 CPU 和内存资源配比,常见的比例差不多是 4 核 4GB、4 核 8GB 这样的。

 

看看对应的 CPU 负载监控信息:

 

 

通过和运维同学的沟通,得到这个节点的配置被限制为 4 核 8GB。

 

这样一来,GC 暂停时间过长的原因就定位到了:

 

  • K8S 的资源隔离和 JVM 未协调好,导致 JVM 看见了 72 个 CPU 内核,默认的并行 GC 线程设置为 72* 5/8 ~= 48 个,但是 K8S 限制了这个 Pod 只能使用 4 个 CPU 内核的计算量,致使 GC 发生时,48 个线程在 4 个 CPU 核心上发生资源竞争,导致大量的上下文切换。

 

处置措施为:

 

  • 限制 GC 的并行线程数量

 

事实证明,打印 GC 日志确实是一个很有用的排查分析方法。

 

限制 GC 的并行线程数量

 

下面是新的启动参数配置:

 

  •  
  •  
  •  
 -Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50 -XX:ParallelGCThreads=4 -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

 

这里指定了 -XX:ParallelGCThreads=4,为什么这么配呢?我们看看这个参数的说明。

 

  •  
-XX:ParallelGCThreads=n

 

设置 STW 阶段的并行 worker 线程数量。 如果逻辑处理器小于等于 8 个,则默认值 n 等于逻辑处理器的数量。

 

如果逻辑处理器大于 8 个,则默认值 n 大约等于处理器数量的 5/8。在大多数情况下都是个比较合理的值。如果是高配置的 SPARC 系统,则默认值 n 大约等于逻辑处理器数量的 5/16。

 

  •  
-XX:ConcGCThreads=n

 

设置并发标记的 GC 线程数量。默认值大约是 ParallelGCThreads 的四分之一。

 

一般来说不用指定并发标记的 GC 线程数量,只用指定并行的即可。

 

重新启动之后,看看 GC 暂停时间指标:

 

 

红色箭头所指示的点就是重启的时间点,可以发现,暂停时间基本上都处于 50ms 范围内。

 

后续的监控发现,这个参数确实解决了问题。

 

案例总结与思考

 

核心经验

 

通过这个完整的排查案例,我们可以得到以下重要经验:没有量化,就没有改进。JVM问题排查和性能调优必须基于具体的监控数据进行。

 

使用的排查手段

 

本案例运用了以下关键技术手段:

 

  • 指标监控:通过Micrometer + Datadog建立完整的监控体系

  • JVM参数调优:合理配置启动内存和垃圾收集器

  • GC日志分析:深入分析GC日志定位根本原因

  • JMX事件监听:通过编程方式获取详细的GC事件信息

 

GC性能维度评估

 

延迟维度:

 

  • 主要关注GC暂停时间

  • 目标:最大暂停时间 < 200ms,平均暂停时间 < 100ms

 

吞吐量维度:

 

  • 业务线程CPU资源占用百分比

  • GC影响因素:暂停时间 + 并发GC的CPU消耗

 

系统容量维度:

 

  • 硬件配置合理性

  • 服务处理能力匹配度

 

关键技术洞察

 

容器化环境的特殊挑战:

 

  • 容器资源限制与JVM感知的不匹配

  • GC线程数配置需要与实际可用CPU核心数对齐

  • K8s资源隔离机制需要与JVM参数协调配置

 

问题排查的系统性方法:

 

  • 现象观察 → 通过监控发现异常

  • 假设验证 → 基于经验提出问题假设

  • 深入分析 → 通过日志等手段验证假设

  • 解决方案 → 针对根因制定解决措施

  • 效果验证 → 持续监控验证解决效果

 

只要确保各项性能指标满足业务需求,资源占用保持在合理范围内,就达到了JVM调优的预期目标。

 

 
作者丨飘渺Jam
来源丨公众号:JAVA日知录 (ID:javadaily)
dbaplus社群欢迎广大技术人员投稿,投稿邮箱:editor@dbaplus.cn
最新评论
访客 2024年04月08日

如果字段的最大可能长度超过255字节,那么长度值可能…

访客 2024年03月04日

只能说作者太用心了,优秀

访客 2024年02月23日

感谢详解

访客 2024年02月20日

一般干个7-8年(即30岁左右),能做到年入40w-50w;有…

访客 2023年08月20日

230721

活动预告