关于java:JVM-优化踩坑记

本文记录了服务 JVM 优化的过程与思路，有对 JVM GC 原理以及对问题排查方向和工具的介绍，也有走弯路和踩坑，分享进去心愿对大家有所帮忙。

本文概要

• 服务异样和排查过程
• RPC 接口超时的排查方向
• 问题根因和解决方案
• JVM GC 原理与优化过程
• 根底工具简要介绍与应用

尝试

RPC 服务调用方反馈服务有时会有超时。

查看服务治理平台发现有客户端调用超时，调用方的超时工夫设置为 1s。

猜想 1：JVM GC 时业务线程进展，导致客户端超时。

遂查看节点的内存使用率，发现在有大量超时异样时，服务节点的内存使用率并没有显著的变动。此时感觉应该不是 GC 导致的问题。（埋下大坑）

猜想 2：RPC 服务 申请解决线程太少，大量申请在队列期待解决，导致客户端超时。

查看 RPC 服务配置的线程为 128。

查看服务排队总量最大为 31，最大值为 2，且大量超时产生时没有排队的申请量。

此时根本判定不是申请排队导致客户端超时。

猜想 3：批量调用接口时，所有申请都没用命中缓存，导致客户端超时。

服务解决申请时，如果没有命中缓存会从 DB，Wtable，HTTP 获取原始数据，而后一一设置缓存，不便下次应用。每次设置缓存的形式如下：

infos.forEach(info -> {cacheService.setCache(CacheKey.V1_DETAILINFO.getKey(), info, CacheExpire.HOUR_1.getTime());
});

获取了每个原始数据后，挨个设置缓存，过期工夫对立为 1 小时。一小时后这些缓存同时过期，过期后的申请就会再次获取原始数据，导致申请响应工夫变长。

优化如下：

infos.forEach(info -> {cacheService.setCache(CacheKey.DETAILINFO.getKey(), info, CacheExpire.HOUR_1.getTime() + random.nextInt(300));
});

同一批设置缓存的过期工夫有一个随机数误差，让这一批缓存数据不至于同时过期，局部缓存过期后的申请工夫相比全副缓存过期就会变短。扩散同时获取原始数据的数量，升高提早。

这一优化上线后，查看监控的确有成果，客户端超时数量锐减。此时，眉头皱缩，感觉问题曾经解决。

好景不长，没过两天，调用方同学反馈又有超时。

猜想 4：数据库连接池不够用，须要 DB 操作时期待连贯，导致客户端超时。

通过 trace 平台查看申请的调用链：

发现在一个申请调用链中有呈现大量的 Wtable 和 Redis 的 get 或者 set 操作，有的高达上百个。按每个 wtable、redis 的操作 1ms 算，那加起来也有上百毫秒。查看代码发现局部接口在循环里获取、设置缓存。然而这种状况不至于导致接口超时，所以没有立刻着手优化。（尽量不要为了不便，在循环里有任何 IO 操作，最好批量 IO）

在有些慢申请中发现 MySQL 操作占用了工夫线的绝大部分，狐疑可能有慢查问。然而查看数据库平台发现超时时刻并没有慢查问。

这时大胆狐疑起了 MySQL 的连接池不够（连接池最大连接数设置为 30），有须要操作 DB 时期待获取连贯，导致 trace 统计 MySQL 操作工夫长然而又没有慢查问的问题。很河狸。

为了不便察看连接池的状态，在服务减少了连接池监控，蕴含连贯数量，沉闷数量，闲暇数量以及期待连贯的数量，监控内容如下图所示：

查看连接池监控，在有客户端超时时，总的连贯数量最高为 14，并没有超过设定的 30，期待获取连贯的也根本没有，阐明咱们猜想连接池不够导致超时的构想也不成立。

一顿操作猛如虎，一看战绩零杠五，心态曾经爆炸。

上不着天; 下不着地

没有其余排查方向，从新狐疑最先排除的 GC 问题。

服务节点的配置是 8C16G，服务应用的垃圾收集器为 CMS，堆内存为 12G。

因为没有输入 GC 日志，只能通过 jstat 简略查看 GC 状况，筹备批改 JVM 参数，输入具体 GC 日志时，在监控平台发现了具体的 JVM 监控：

在 11 点钟 FGC 的工夫靠近 4s，老年代使用率从 80% 降到 20% 多。堆内存为 12G，新生代配置 4G，老年代为 8G，意味着回收近 4.8G 老年代内存耗时 4s。此时这个节点有客户端超时的状况。

为什么 FGC 的工夫会忽然这么长？五月下旬发现容器的内存有 16G 但堆内存只配了 8G，所以将堆内存调整为 12G。从历史监控数据能够看到调整之前每天一次 FGC 的频率，变成每 1.7 天一次，FGC 的工夫 1s 减少到 3s。

因为堆内存较大，CMS 比拟适宜小内存的 JVM，大内存时在 FGC 须要回收较多对象时会造成长时间进展。

目前在小内存利用上 CMS 的体现大概率依然要会优于 G1，而在大内存利用上 G1 则大多能施展其劣势，这个优劣势的 Java 堆容量平衡点通常在 6GB 至 8GB 之间，当然，以上这些也仅是经验之谈，不同利用须要因地制宜地理论测试能力得出最合适的论断，随着 HotSpot 的开发者对 G1 的一直优化，也会让比照后果持续向 G1 歪斜。《深刻了解 Java 虚拟机》

所以没有优化 CMS FGC 的耗时间接将垃圾收集器调整为 G1，并输入 GC 日志：

-Xms12g 
-Xmx12g 
-Xss1024K 
-XX:MetaspaceSize=128m 
-XX:MaxMetaspaceSize=256m 
-XX:+UseG1GC 
-XX:MaxGCPauseMillis=200
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/opt/logs/server.hprof 
-XlogGC:/opt/logs/GC-server.log 
-verbose:GC 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails

察看三天发现问题解决，没有 FGC, YGC 频率升高，GC time 降落：

G1 GC 优化

正当我截出下面三张图时，传来噩耗，又呈现大量超时，查看 GC 日志：

// 初始标记阶段 - Initial Mark
2022-07-01T10:08:05.605+0800: 236284.460: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0225183 secs]
   [Eden: 5460.0M(5460.0M)->0.0B(5484.0M) Survivors: 32.0M->20.0M Heap: 10.7G(12.0G)->5500.9M(12.0G)]
 [Times: user=0.07 sys=0.02, real=0.03 secs] 
 
2022-07-01T10:08:05.627+0800: 236284.482: [GC concurrent-root-region-scan-start]
2022-07-01T10:08:05.640+0800: 236284.495: [GC concurrent-root-region-scan-end, 0.0124812 secs]
​
// 并发标记阶段 - Concurrent Mark
2022-07-01T10:08:05.640+0800: 236284.495: [GC concurrent-mark-start]
2022-07-01T10:08:05.856+0800: 236284.711: [GC concurrent-mark-end, 0.2160935 secs]
​
// 最终标记阶段 - Remark
2022-07-01T10:08:05.860+0800: 236284.715: [GC remark 2022-07-01T10:08:05.860+0800: 236284.715: [Finalize Marking, 0.0010205 secs] 2022-07-01T10:08:05.861+0800: 236284.716: [GC ref-proc, 4.9682204 secs] 2022-07-01T10:08:10.829+0800: 236289.684: [Unloading, 0.0406443 secs], 5.0155142 secs]
 [Times: user=5.06 sys=0.23, real=5.01 secs] 
// 清理阶段 - Clean Up
2022-07-01T10:08:10.879+0800: 236289.734: [GC cleanup 5564M->5544M(12G), 0.0093801 secs]
 [Times: user=0.04 sys=0.02, real=0.01 secs] 
2022-07-01T10:08:10.889+0800: 236289.744: [GC concurrent-cleanup-start]
2022-07-01T10:08:10.889+0800: 236289.744: [GC concurrent-cleanup-end, 0.0000416 secs]
​
2022-07-01T10:08:51.933+0800: 236330.788: [GC pause (G1 Evacuation Pause) (young), 0.0200670 secs]
[Eden: 5484.0M(5484.0M)->0.0B(576.0M) Survivors: 20.0M->36.0M Heap: 10.7G(12.0G)->5498.2M(12.0G)]
// 第一次 mixed GC
2022-07-01T10:08:55.212+0800: 236334.067: [GC pause (G1 Evacuation Pause) (mixed), 0.1236984 secs]
[Eden: 576.0M(576.0M)->0.0B(580.0M) Survivors: 36.0M->32.0M Heap: 6074.2M(12.0G)->5177.9M(12.0G)]
 [Times: user=0.91 sys=0.00, real=0.12 secs] 
// 第二次 mixed GC
2022-07-01T10:08:58.241+0800: 236337.096: [GC pause (G1 Evacuation Pause) (mixed), 0.2377220 secs]
[Eden: 580.0M(580.0M)->0.0B(584.0M) Survivors: 32.0M->28.0M Heap: 5757.9M(12.0G)->4877.3M(12.0G)]
 [Times: user=1.29 sys=0.37, real=0.24 secs] 
// 第三次 mixed GC
2022-07-01T10:09:01.041+0800: 236339.896: [GC pause (G1 Evacuation Pause) (mixed), 0.2694744 secs]
[Eden: 584.0M(584.0M)->0.0B(584.0M) Survivors: 28.0M->28.0M Heap: 5461.3M(12.0G)->4589.9M(12.0G)]
 [Times: user=1.66 sys=0.31, real=0.27 secs] 
// 第四次 mixed GC
2022-07-01T10:09:03.574+0800: 236342.429: [GC pause (G1 Evacuation Pause) (mixed), 0.2417761 secs]
[Eden: 584.0M(584.0M)->0.0B(580.0M) Survivors: 28.0M->32.0M Heap: 5173.9M(12.0G)->4312.0M(12.0G)]
 [Times: user=1.48 sys=0.32, real=0.24 secs] 
// 第五次 mixed GC
2022-07-01T10:09:06.137+0800: 236344.992: [GC pause (G1 Evacuation Pause) (mixed), 0.2646752 secs]
   [Eden: 580.0M(580.0M)->0.0B(580.0M) Survivors: 32.0M->32.0M Heap: 4892.0M(12.0G)->4038.0M(12.0G)]
 [Times: user=1.59 sys=0.21, real=0.26 secs] 
// 第六次 mixed GC
2022-07-01T10:09:08.762+0800: 236347.617: [GC pause (G1 Evacuation Pause) (mixed), 0.1496482 secs]
[Eden: 580.0M(580.0M)->0.0B(572.0M) Survivors: 32.0M->40.0M Heap: 4618.0M(12.0G)->3911.4M(12.0G)]
 [Times: user=1.05 sys=0.05, real=0.15 secs] 
 
 
2022-07-01T10:09:23.415+0800: 236362.270: [GC pause (G1 Evacuation Pause) (young), 0.0135612 secs]
   [Eden: 588.0M(588.0M)->0.0B(584.0M) Survivors: 24.0M->28.0M Heap: 4535.6M(12.0G)->3953.6M(12.0G)]
 [Times: user=0.06 sys=0.03, real=0.02 secs] 
 // 屡次 young GC 后，新生代扩容
2022-07-01T10:09:26.096+0800: 236364.951: [GC pause (G1 Evacuation Pause) (young), 0.0145410 secs]
   [Eden: 584.0M(584.0M)->0.0B(7028.0M) Survivors: 28.0M->24.0M Heap: 4537.6M(12.0G)->3950.7M(12.0G)]
 [Times: user=0.07 sys=0.02, real=0.02 secs] 

这次的日志能够总结出上面几个问题：

为什么产生 mixed GC？

当达到 IHOP 阈值，-XX:InitiatingHeapOccupancyPercent（默认 45%）时，老年代应用内存占到堆总大小的 45% 的时候，G1 将开始并发标记阶段 + Mixed GC。

GC 日志能够看到初始标记时老年代大略 5500.9M，堆内存 12G，5500 / 12000 ≈ 45.8%。

为什么 GC ref-proc 耗时这么长？

ref-proc 其实是对各种脆弱虚援用等的解决。

日志中 ref-proc 4.9682204s 就是解决 soft、weak、phantom、final、JNI 等等援用的工夫。

初步狐疑是 softReference 或者是 finalReference 导致耗时较长。

为什么新生代 5484.0M 变为 576.0M？

remark 阶段的耗时较长，导致 G1 新生代自适应策略认为须要尽可能的调小新生代大小，以满足 200ms 的冀望进展工夫，然而新生代最小值 -XX:G1NewSizePercent 在未配置的状况下为 5%，大略为 12G * 5% = 600M 左右。

为什么间断 6 次 mixed GC？

-XX:G1MixedGCCountTarget，默认为 8，这个参数标识最初的混合回收阶段会执行 8 次，一次只回收掉一部分的 Region，而后零碎持续运行，过一小段时间之后，又再次进行混合回收，反复 8 次。执行这种间断的混合回收，就能够把每次的混合回收工夫管制在咱们须要的进展工夫之内了，同时达到垃圾清理的成果。

清理了 6 次就曾经满足了回收成果，所以没有持续 mixed GC。

为什么新生代 584.0M 变为 7028.0M？

mixed GC 之后的 YGC 耗时与冀望进展工夫之间还有较大间隔，所以 G1 新生代自适应策略认为加大新生代空间也能满足冀望进展工夫，并能缩小 YGC 的频率，所以减少了新生代的大小。

这么剖析下来发现这一系列的问题都是因为 GC ref-proc 耗时较长导致的，而后在 G1 官网发现如下倡议：

Reference Object Processing Takes Too Long

Information about the time taken for processing of Reference Objects is shown in the Ref Proc and Ref Enq phases. During the Ref Proc phase, G1 updates the referents of Reference Objects according to the requirements of their particular type. In Ref Enq, G1 enqueues Reference Objects into their respective reference queue if their referents were found dead. If these phases take too long, then consider enabling parallelization of these phases by using the option -XX:+ParallelRefProcEnabled.

粗心为默认状况 ref-proc 阶段是单线程执行的，若该阶段耗时较长，能够增加 -XX:+ParallelRefProcEnabled 参数，尽量在该阶段应用多线程解决，在增加该参数的根底上，咱们还新增了 -XX:+PrintReferenceGC，不便在日志中看到 ref-proc 阶段中的耗时详情：

-Xms12g 
-Xmx12g 
-Xss1024K 
-XX:MetaspaceSize=128m 
-XX:MaxMetaspaceSize=256m 
-XX:+UseG1GC 
-XX:MaxGCPauseMillis=200 
-XX:+ParallelRefProcEnabled 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/opt/logs/server.hprof 
-XlogGC:/opt/logs/GC-server.log 
-verbose:GC 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintReferenceGC

上线之后期待了 2.5 天，mixed GC 如约而至：

[GC remark 2022-07-03T20:20:45.784+0800: 200955.276: [Finalize Marking, 0.0009754 secs] 
2022-07-03T20:20:45.785+0800: 200955.277: [GC ref-proc2022-07-03T20:20:45.785+0800: 200955.277: [SoftReference, 5985 refs, 0.0016774 secs]
2022-07-03T20:20:45.787+0800: 200955.279: [WeakReference, 833 refs, 0.0004107 secs]
2022-07-03T20:20:45.787+0800: 200955.279: [FinalReference, 61 refs, 0.0009986 secs]
2022-07-03T20:20:45.788+0800: 200955.280: [PhantomReference, 2922 refs, 217 refs, 0.6387731 secs]
2022-07-03T20:20:46.427+0800: 200955.919: [JNI Weak Reference, 0.0002668 secs], 0.6448878 secs] 2022-07-03T20:20:46.430+0800: 200955.922: [Unloading, 0.0426223 secs], 0.6948057 secs]
 [Times: user=5.13 sys=0.22, real=0.70 secs] 

新增 -XX:+ParallelRefProcEnabled 参数后，ref-proc 阶段耗时共为 0.6448878s，较 4.9682204s 有了微小晋升，尽管没有超时呈现，但还是较长，不能容忍，须要持续优化。

ref-proc 阶段次要耗时在解决 PhantomReference 上，共耗时 0.64s。

PhantomReference 是什么？

• 虚援用也称为“幽灵援用”，它是最弱的一种援用关系。
• 如果一个对象仅持有虚援用，那么它就和没有任何援用一样，在任何时候都可能被垃圾回收器回收。
• 为一个对象设置虚援用关联的惟一目标只是为了能在这个对象被收集器回收时收到一个零碎告诉。
• 当垃圾回收器筹备回收一个对象时，如果发现它还有虚援用，就会在垃圾回收后，将这个虚援用退出援用队列，在其关联的虚援用出队前，不会彻底销毁该对象。所以能够通过查看援用队列中是否有相应的虚援用来判断对象是否曾经被回收了。

大略理解了一点 PhantomReference 是什么之后，为了搞清楚 PhantomReference 类型的到底是哪些对象，咱们查看堆文件中的对象散布，发现 PhantomReference 类型大部分都是这个类 com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference，有 2439 个。（dump 文件时务必摘除该节点的流量，否则影响线上申请）

217:          2439          78048  com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference

ConnectionPhantomReference 是什么对象？

在 MySql jdbc 驱动代码中发现，NonRegisteringDriver 类有个虚援用汇合 connectionPhantomRefs 用于存储所有的数据库连贯，NonRegisteringDriver.trackConnection 办法负责把新创建的连贯放入 connectionPhantomRefs 汇合：

public class NonRegisteringDriver implements Driver {
  ...
  protected static final ConcurrentHashMap<ConnectionPhantomReference, ConnectionPhantomReference> connectionPhantomRefs = new ConcurrentHashMap();
   
  protected static void trackConnection(com.mysql.jdbc.Connection newConn) {ConnectionPhantomReference phantomRef = new ConnectionPhantomReference((ConnectionImpl)newConn, refQueue);
        connectionPhantomRefs.put(phantomRef, phantomRef);
    }
  ...
}

public ConnectionImpl(String hostToConnectTo, int portToConnectTo, Properties info, String databaseToConnectTo, String url) throws SQLException {
    ...
    NonRegisteringDriver.trackConnection(this);
  ...
}

应用 HikariCP 连接池为何还会生成这么多连贯？

HikariCP 连接池有个 maxLifeTime 配置项，意思为连贯的最长存活工夫，超过该工夫则回收该连贯，而后生成新连贯。咱们的配置中没有设置该值，源码中默认为 30 分钟，意味着咱们生成的连贯最多应用 30 分钟。

// HikariCP maxLifeTime 默认值
MAX_LIFETIME = TimeUnit.MINUTES.toMillis(30L);

因而咱们虽应用了连接池，也会一直的创立新连贯。新的连接不断减少 NonRegisteringDriver 类中虚援用汇合 connectionPhantomRefs 的虚援用数量，累计肯定数量之后减少 ref-proc 的耗时。

问题定位了，咱们只能缩小虚援用汇合中的虚援用数量，也就是缩小生成新连贯的速度，最大限度应用无效连贯。

HikariCP 作者有如下倡议：

But if you update your HikariCP version to 2.7.4 with JDK 8, i also recommend you two points:

to set maxLifeTime value to be at least 30000ms.

to set maxLifeTime value few minute less than mysql’s wait_timeout(show variables like“%timeout%”) to avoid broken connection exception.

maxLifeTime 的值至多为 30000ms。

maxLifeTime 的值比数据库的 wait_timeout 值少几分钟为好。

咱们 MySql 的 wait_timeout 默认为 3600 秒，所以将 maxLifeTime 设置为 59 分钟，同时将闲暇连贯的存活工夫调整为 30 分钟，最大限度的缩小新连贯的生成。

dbConfig.setMaxLifetime(TimeUnit.MINUTES.toMillis(59L));
dbConfig.setIdleTimeout(TimeUnit.MINUTES.toMillis(30L));

连接池优化上线 3.5 天后，再次迎来了 mixed GC：

2022-07-07T22:41:29.227+0800: 300734.449: [GC remark 2022-07-07T22:41:29.227+0800: 300734.449: [Finalize Marking, 0.0012842 secs] 
2022-07-07T22:41:29.228+0800: 300734.451: [GC ref-proc2022-07-07T22:41:29.228+0800: 300734.451: [SoftReference, 6013 refs, 0.0020042 secs]
2022-07-07T22:41:29.230+0800: 300734.453: [WeakReference, 1138 refs, 0.0005509 secs]
2022-07-07T22:41:29.231+0800: 300734.453: [FinalReference, 196 refs, 0.0019740 secs]
2022-07-07T22:41:29.233+0800: 300734.455: [PhantomReference, 2350 refs, 235 refs, 0.5898343 secs]
2022-07-07T22:41:29.823+0800: 300735.045: [JNI Weak Reference, 0.0002747 secs], 0.5970905 secs] 
2022-07-07T22:41:29.825+0800: 300735.048: [Unloading, 0.0432827 secs], 0.6473847 secs]
 [Times: user=4.73 sys=0.23, real=0.65 secs] 

尽管咱们调长了连接池连贯的生命时长，然而这次上线 3.5 蠢才产生 mixed GC，积攒的连贯虚援用还是没怎么变少，有 2000 多个，ref-proc 阶段的耗时仍旧长达 0.6473847s。

因为 MySql 的 wait_timeout 值为 3600 秒，maxLifeTime 的值也无奈超过一个小时，所以 ref-proc 耗时仍不现实，会导致 G1 将新生代调整的较小，间断触发 GC。

鼎力出奇观

虚援用往往做为一种兜底策略，防止用户遗记开释资源，引发内存泄露。咱们应用连接池会谨严解决资源的开释，能够不采纳兜底策略，间接删除中 connectionPhantomRefs 中的虚援用，使对象不可达，在 GC 时间接回收，从而缩小 PhantomReference 的解决工夫。

应用定时工作清理 connectionPhantomRefs：

// 每两小时清理 connectionPhantomRefs，缩小对 mixed GC 的影响
SCHEDULED_EXECUTOR.scheduleAtFixedRate(() -> {
  try {Field connectionPhantomRefs = NonRegisteringDriver.class.getDeclaredField("connectionPhantomRefs");
    connectionPhantomRefs.setAccessible(true);
    Map map = (Map) connectionPhantomRefs.get(NonRegisteringDriver.class);
    if (map.size() > 50) {map.clear();
    }
  } catch (Exception e) {log.error("connectionPhantomRefs clear error!", e);
  }
}, 2, 2, TimeUnit.HOURS);

定时清理 connectionPhantomRefs 的操作在某种程度上来说还是有点暴力，保险起见咱们在测试平台进行了几天的稳定性测试，没有什么问题后再上线。

3.5 天后迎来喜讯，YGC 耗时 20 毫秒左右，mixed GC 耗时 10-40 毫秒左右，ref-proc 阶段耗时共为 10 毫秒，PhantomReference 阶段耗时 0.5 毫秒，合乎预期：

2022-07-11T20:21:09.227+0800: 267282.500: [GC ref-proc2022-07-11T20:21:09.227+0800: 267282.500: [SoftReference, 6265 refs, 0.0018357 secs]
2022-07-11T20:21:09.229+0800: 267282.502: [WeakReference, 995 refs, 0.0004459 secs]
2022-07-11T20:21:09.229+0800: 267282.502: [FinalReference, 2312 refs, 0.0063426 secs]
2022-07-11T20:21:09.236+0800: 267282.508: [PhantomReference, 0 refs, 268 refs, 0.0005663 secs]
2022-07-11T20:21:09.236+0800: 267282.509: [JNI Weak Reference, 0.0002658 secs], 0.0116221 secs] 
2022-07-11T20:21:09.238+0800: 267282.511: [Unloading, 0.0400431 secs], 0.0540532 secs]
 [Times: user=0.20 sys=0.11, real=0.06 secs] 
​
[Eden: 5016.0M(5016.0M)->0.0B(532.0M) Survivors: 24.0M->28.0M Heap: 9941.0M(11.0G)->4928.1M(11.0G)]
 [Times: user=0.10 sys=0.00, real=0.02 secs] 

老年代应用比例图：

YGC 次数图：

YGC 耗时图：

mixed GC 后老年代 85% 到 20%；一分钟内产生 7 次 YGC 或者 mixed GC，共耗时 126 毫秒，均匀每次 18 毫秒，完全符合咱们的进展要求。尽管 mixed GC 的耗时曾经升高，然而发现 G1 还是会将新生代降到最小，也就是堆的 5%，可能会在后续的几十秒内每两秒一次 GC（每次耗时 10-40 毫秒 )，如果你感觉不能忍耐的话，能够通过 -XX:G1NewSizePercent 来管制最小新生代的大小。

服务的 GC 时长由原来的 CMS FGC 4s 到当初 G1 mixed GC 10-40ms，也没有因为 GC 导致的超时问题了，至此服务的 GC 优化告一段落，然而后续还须要对业务导致的超时进行优化。

G1 YGC 异样耗时探索

后续察看 JVM 监控时发现有个节点的 YGC 工夫异样，失常都是几十毫秒，但这次高达 250 毫秒（MaxGCPauseMillis=200）：

查看该节点的 GC 日志，

失常耗时的 YGC 日志：

2022-06-29T17:11:54.560+0800: 88938.859: [GC pause (G1 Evacuation Pause) (young), 0.0192881 secs]
   [Parallel Time: 12.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 88938859.5, Avg: 88938859.5, Max: 88938859.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.0, Avg: 2.8, Max: 5.0, Diff: 3.1, Sum: 22.0]
      [Update RS (ms): Min: 0.7, Avg: 2.9, Max: 3.7, Diff: 2.9, Sum: 23.0]
         [Processed Buffers: Min: 47, Avg: 71.4, Max: 100, Diff: 53, Sum: 571]
      [Scan RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.1, Sum: 3.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 6.4, Avg: 6.5, Max: 6.6, Diff: 0.2, Sum: 52.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]
      [GC Worker Total (ms): Min: 12.5, Avg: 12.6, Max: 12.7, Diff: 0.2, Sum: 100.9]
      [GC Worker End (ms): Min: 88938872.1, Avg: 88938872.2, Max: 88938872.2, Diff: 0.1]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 5.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 3.6 ms]
   [Eden: 7344.0M(7344.0M)->0.0B(7340.0M) Survivors: 28.0M->32.0M Heap: 9585.0M(12.0G)->2243.5M(12.0G)]
 [Times: user=0.08 sys=0.03, real=0.02 secs]

异样耗时的 YGC 日志：

2022-06-29T17:11:19.276+0800: 88903.574: [GC pause (G1 Evacuation Pause) (young), 0.2305707 secs]
   [Parallel Time: 223.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 88903574.7, Avg: 88903574.7, Max: 88903574.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 2.9, Max: 5.4, Diff: 3.3, Sum: 23.5]
      [Update RS (ms): Min: 0.5, Avg: 3.0, Max: 3.9, Diff: 3.3, Sum: 24.0]
         [Processed Buffers: Min: 54, Avg: 71.6, Max: 91, Diff: 37, Sum: 573]
      [Scan RS (ms): Min: 0.3, Avg: 0.4, Max: 0.5, Diff: 0.2, Sum: 3.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 5.8, Avg: 32.3, Max: 216.9, Diff: 211.1, Sum: 258.7]
      [Termination (ms): Min: 0.0, Avg: 184.7, Max: 211.3, Diff: 211.3, Sum: 1477.6]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 223.4, Avg: 223.5, Max: 223.5, Diff: 0.1, Sum: 1787.7]
      [GC Worker End (ms): Min: 88903798.1, Avg: 88903798.2, Max: 88903798.2, Diff: 0.1]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 6.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 3.9 ms]
   [Eden: 7344.0M(7344.0M)->0.0B(7344.0M) Survivors: 28.0M->28.0M Heap: 9584.6M(12.0G)->2241.0M(12.0G)]
 [Times: user=1.49 sys=0.27, real=0.23 secs]

失常 YGC 日志为 19 毫秒左右，异样为 230 毫秒，比照发现如下异样：

// 失常
[Object Copy (ms): Min: 6.4, Avg: 6.5, Max: 6.6, Diff: 0.2, Sum: 52.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Times: user=0.08 sys=0.03, real=0.02 secs]

// 异样
[Object Copy (ms): Min: 5.8, Avg: 32.3, Max: 216.9, Diff: 211.1, Sum: 258.7]
[Termination (ms): Min: 0.0, Avg: 184.7, Max: 211.3, Diff: 211.3, Sum: 1477.6]
[Times: user=1.49 sys=0.27, real=0.23 secs]

概念介绍

Object Copy (ms)：内存回收过程中将存活对象迁徙到新的 region 和 survivor，也有一部分会降职到老年代 region，对象拷贝的工夫。Min 为多线程回收中起码的耗时，Avg 为均匀耗时，Max 为最大耗时，Diff 为拷贝对象耗时最大差值，Sum 为所有 GC 线程拷贝对象的工夫总和。

Termination (ms)：GC 工作线程终止工夫。Min 为线程终止起码的耗时，Avg 为均匀耗时，Max 为最大耗时，Diff 为耗时最大差值，Sum 为所有 GC 线程终止耗时的总和。

user：JVM 代码耗时。

sys：操作系统耗时。

real：业务线程进展耗时。

日志异同

能够看到异样日志中 Termination 工夫很高，最大耗时 211 毫秒，然而失常的 GC 日志中 Termination 耗时都是 0。

异样日志中的 Object Copy 工夫较高，起码 5.8 毫秒，最大 216 毫秒，差值高达 211 毫秒。然而在失常日志中 Object Copy 工夫比拟均匀，都为几毫秒。

异常情况下操作系统耗时 sys = 0.27 比失常 sys = 0.03，高了 9 倍。

初步剖析是某个线程在拷贝对象时有些异样，导致 Termination 工夫长。所以根因是 Object Copy 工夫。

假如 8 个 GC 线程中有一个异样（配置 GC Workers: 8），最大耗时为 211 毫秒，另七个线程为失常 GC 线程的均匀耗时 6.5 毫秒，那计算均匀耗时为：

(6.5 * 7 + 211) / 8 = 32.0625，与异样日志中的 Avg: 32.3 基本一致，印证了有一个 GC 线程异样的猜测。

为何异样

查了很多材料没有确切答案，但在 stackoverflow 找到一个貌似可能的答案：

swap activity or transparent huge pages are likely suspects.

对于操作系统耗时较多：

Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide 有相似阐明：

Common known issues for high system time are:

• Particularly in Linux, coalescing of small pages into huge pages by the Transparent Huge Pages (THP) feature tends to stall random processes, not just during a pause. Because the VM allocates and maintains a lot of memory, there is a higher than usual risk that the VM will be the process that stalls for a long time. Refer to the documentation of your operating system on how to disable the Transparent Huge Pages feature.

意思可能是替换内存或者 Transparent Huge Pages (THP) 导致内存操作耗时较长。

查看容器是否启用 Transparent Huge Pages (THP)：

always madvise [never] 表明禁用。

查看容器磁盘 IO 监控：

发现异常 YGC 工夫左近的确有大量的 IO 操作记录。有可能与替换内存无关。

目前只发现多数异样 YGC 耗时的记录，能力无限没有持续深究基本问题，暂且定位为虚构运行环境导致系统操作耗时较长导致的问题，有大佬理解能够指导指导。

总结

JVM 启动后会逐渐申请至最大堆内存，GC 只将内存清理，并不会开释给零碎，所以 FGC 时在节点的内存使用率上看不到内存稳定。内存使用率图表导致了谬误的判断，错失第一工夫发现问题的机会。好在此次排查过程减少了相似问题的排查教训，裸露了一些问题，也减少了数据库连接池的监控。

参考

Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide

从一起 GC 血案谈到反射原理

一次简略的 G1GC 参数调优

新生代自适应策略

PhantomReference 引发的 GC 问题

数据库连接池内存透露问题的剖析和解决方案

一位后端写码师，一位光明操持制造者。公众号：DailyHappy