怎么建设一个音乐网站,长沙做网站微联讯点不错,公司网站建设多少费用济南兴田德润评价,北京企业建设网站前言
本文将通过一个真实的生产环境案例#xff0c;详细展示如何系统性地排查和解决JVM垃圾收集问题。这个案例涵盖了从问题发现、分析诊断到最终解决的完整过程#xff0c;对于理解JVM调优实战具有重要的参考价值。
系统背景
我们的服务是一个高并发的微服务应用#xf…前言
本文将通过一个真实的生产环境案例详细展示如何系统性地排查和解决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.92CPU使用率约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 8GC选择未指定使用默认的ParallelGC堆内存最大和初始堆内存均为4GB
初步问题假设
怀疑点ParallelGC可能是问题根源
设计目标ParallelGC主要追求系统最大吞吐量权衡策略为了吞吐量优化会牺牲单次GC的暂停时间推测结论可能因此导致暂停时间过长
第一次优化尝试切换到G1GC
优化策略选择
选择G1垃圾收集器的理由
稳定性在JDK 8的新版本中G1已经相当稳定性能表现具有良好的延迟控制能力适用场景更适合低延迟要求的应用
配置过程
初次配置失败
# 参数配置错误导致启动失败
-Xmx4g -Xms4g -XX:UseG1GC -XX:MaxGCPauseMills50ms错误分析
参数名拼写错误MaxGCPauseMills → MaxGCPauseMillis参数值格式错误50ms → 50
修正后配置
-Xmx4g -Xms4g -XX:UseG1GC -XX:MaxGCPauseMillis50初步效果验证
服务启动成功通过健康检测切换到新节点后监控显示 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, null, null);
}通过这种方式我们可以在程序中监听 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:MaxGCPauseMillis50
-Xloggc:gc.log -XX:PrintGCDetails -XX:PrintGCDateStamps重新启动希望这次能排查出问题的原因。 运行一段时间又发现了超长的暂停时间。
分析 GC 日志
因为不涉及敏感数据那么我们把 GC 日志下载到本地进行分析。
定位到这次暂停时间超长的 GC 事件关键的信息如下所示
Java HotSpot(TM) 64-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:InitialHeapSize4294967296 -XX:MaxGCPauseMillis50 -XX:MaxHeapSize4294967296-XX:PrintGC -XX:PrintGCDateStamps -XX:PrintGCDetails -XX:PrintGCTimeStamps -XX:UseCompressedClassPointers -XX:UseCompressedOops -XX:UseG1GC 2020-02-24T18:02:31.8530800: 2411.124: [GC pause (G1 Evacuation Pause) (young), 1.8683418 secs][Parallel Time: 1861.0 ms, GC Workers: 48][GC Worker Start (ms): Min: 2411124.3, Avg: 2411125.4, Max: 2411126.2, Diff: 1.9][Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 2.7, Diff: 2.7, Sum: 16.8][Update RS (ms): Min: 0.0, Avg: 3.6, Max: 6.8, Diff: 6.8, Sum: 172.9][Processed Buffers: Min: 0, Avg: 2.3, Max: 8, Diff: 8, Sum: 111][Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 7.7][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3][Object Copy (ms): Min: 1851.6, Avg: 1854.6, Max: 1857.4, Diff: 5.8, Sum: 89020.4][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.6][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 48][GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 14.7][GC Worker Total (ms): Min: 1858.0, Avg: 1859.0, Max: 1860.3, Diff: 2.3, Sum: 89233.3][GC Worker End (ms): Min: 2412984.1, Avg: 2412984.4, Max: 2412984.6, Diff: 0.5][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 1.5 ms][Other: 5.8 ms][Choose CSet: 0.0 ms][Ref Proc: 1.7 ms][Ref Enq: 0.0 ms][Redirty Cards: 1.1 ms][Humongous Register: 0.1 ms][Humongous Reclaim: 0.0 ms][Free CSet: 2.3 ms][Eden: 2024.0M(2024.0M)-0.0B(2048.0K) Survivors: 2048.0K-254.0M Heap: 3633.6M(4096.0M)-1999.3M(4096.0M)][Times: user1.67 sys14.00, real1.87 secs] 前后的 GC 事件都很正常也没发现 FullGC 或者并发标记周期但找到了几个可疑的点。
physical 144145548k(58207948k free)JVM 启动时物理内存 137GB空闲内存 55GB。[Parallel Time: 1861.0 ms, GC Workers: 48]垃圾收集器工作线程 48 个。
GC 日志中揭露了几个关键信息
user1.67用户线程耗时 1.67ssys14.00系统调用和系统等待时间 14sreal1.87 secs实际暂停时间 1.87sGC 之前年轻代使用量 2GB堆内存使用量 3.6GB存活区 2MB可推断出老年代使用量 1.6GBGC 之后年轻代使用量为 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:MaxGCPauseMillis50 -XX:ParallelGCThreads4-Xloggc:gc.log -XX:PrintGCDetails -XX:PrintGCDateStamps这里指定了 -XX:ParallelGCThreads4为什么这么配呢我们看看这个参数的说明。
-XX:ParallelGCThreadsn设置 STW 阶段的并行 worker 线程数量。 如果逻辑处理器小于等于 8 个则默认值 n 等于逻辑处理器的数量。
如果逻辑处理器大于 8 个则默认值 n 大约等于处理器数量的 5/8。在大多数情况下都是个比较合理的值。如果是高配置的 SPARC 系统则默认值 n 大约等于逻辑处理器数量的 5/16。
-XX:ConcGCThreadsn设置并发标记的 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调优的预期目标。
