绪言开云kaiyun中国官方网站
本文将通过一个真确的坐褥环境案例，谨慎展示奈何系统性地排查和惩办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社群接待宽敞手艺东谈主员投稿开云kaiyun中国官方网站，投稿邮箱：editor@dbaplus.cn
发布于：广东省