媒介

本文将通过一个真确的出产环境案例，详备展示若何系统性地排查和处分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

问题表象

张开剩余95%

问题形色

在日常监控中，咱们发现一个职业节点出现了严重的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, 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:MaxGCPauseMillis=50

-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: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 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: 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社群接待繁密工夫东说念主员投稿体育游戏app平台，投稿邮箱：editor@dbaplus.cn

发布于：广东省