1. 背景
我方有一应用，偶尔会出现GC时间过长（间隔约4小时），导致性能波动的问题(接口最长需要耗时3秒以上)。经排查为G1垃圾回收器参数配置不当 叠加 MySQL 链接超过闲置时间回收，产生大量的虚引用，导致G1在执行老年代混合GC，标记阶段耗时过长导致。以下为对此问题的分析及问题总结。
此外，此应用因为使用redis缓存为数据库缓存一段时间的热点数据，导致业务起量创建数据库链接后，会很容易被闲置，容易被数据库连接池判定为闲置过长而清理。
应用背景
JDK1.8 , mysql-connector-java-5.1.30, commons-dbcp-1.4, spring-4.3.20.RELEASE
硬件：8核16GB;
JVM启动参数概要：
-Xms9984m -Xmx9984m -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:MaxDirectMemorySize=512m -XX:ParallelGCThreads=8 -XX:CICompilerCount=4 -XX:ConcGCThreads=4 -server -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:G1HeapRegionSize=32M -XX:SurvivorRatio=10 -XX:MaxTenuringThreshold=5 -XX:InitiatingHeapOccupancyPercent=45 -XX:G1ReservePercent=20 -XX:G1MixedGCLiveThresholdPercent=80 -XX:MaxGCPauseMillis=100 -XX:+ExplicitGCInvokesConcurrent -XX:+PrintGCDetails -XX:+PrintReferenceGC -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/export/Logs/app/tomcat7-gc.log
dbcp配置：
maxActive=20
initialSize=10
maxIdle=10
minIdle=5
minEvictableIdleTimeMillis=180000
timeBetweenEvictionRunsMillis=20000
validationQuery=select 1
配置说明：
maxActive=20: 连接池中最多能够同时存在的连接数，配置为20。- `initialSize=10: 数据源初始化时创建的连接数，配置为10。
maxIdle=10: 连接池中最大空闲连接数，也就是说当连接池中的连接数超过10个时，多余的连接将会被释放，配置为10。minIdle=5: 连接池中最小空闲连接数，也就是说当连接池中的连接数少于5个时，会自动添加新的连接到连接池中，配置为5。- `minEvictableIdleTimeMillis=180000: 连接在连接池中最小空闲时间，这里配置为3分钟，表示连接池中的连接在空闲3分钟之后将会被移除，避免长时间占用资源。
timeBetweenEvictionRunsMillis=20000: 连接池中维护线程的运行时间间隔，单位毫秒。这里配置为20秒，表示连接池中会每隔20秒检查连接池中的连接是否空闲过长时间并且需要关闭。validationQuery=select 1: 验证连接是否有效的SQL语句，这里使用了一个简单的SELECT 1查询。
关键词
java G1GC ， G1参数调优，G1 STW 耗时过长，com.mysql.jdbc.NonRegisteringDriver，ConnectionPhantomReference，PhantomReference， GC ref-proc spent too much time ，GC remark，Finalize Marking
2. 问题排查
可用率报警
日志查询
查询本地日志，找到下游timeout的接口日志, 并找到相关IP为：11.#.#.201
查看jvm监控
这里有个问题，因为系统工具ump对jvm 的监控，只关注young gc & full gc, 遗漏了G1的混合GC， 导致直接通过系统监控未及时发现GC过长的问题。到后面下载了gc日志，最终分析得到了 GC时间超过3.7秒的监控结果，这也是问题的根源。
3. 问题分析
GC日志分析
2023-06-03T14:40:31.391+0800: 184748.113: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.1017154 secs]
[Parallel Time: 70.3 ms, GC Workers: 6]
[GC Worker Start (ms): Min: 184748113.5, Avg: 184748113.6, Max: 184748113.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 1.9, Avg: 2.1, Max: 2.2, Diff: 0.3, Sum: 12.3]
[Update RS (ms): Min: 9.7, Avg: 9.9, Max: 10.4, Diff: 0.7, Sum: 59.6]
[Processed Buffers: Min: 12, Avg: 39.5, Max: 84, Diff: 72, Sum: 237]
[Scan RS (ms): Min: 0.1, Avg: 0.7, Max: 1.2, Diff: 1.1, Sum: 4.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 56.9, Avg: 57.5, Max: 57.7, Diff: 0.8, Sum: 344.8]
[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: 6]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 70.1, Avg: 70.1, Max: 70.2, Diff: 0.1, Sum: 420.9]
[GC Worker End (ms): Min: 184748183.7, Avg: 184748183.7, Max: 184748183.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 31.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 30.1 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 1760.0M(1760.0M)->0.0B(2080.0M) Survivors: 192.0M->224.0M Heap: 6521.7M(9984.0M)->4912.0M(9984.0M)]
Heap after GC invocations=408 (full 0):
garbage-first heap total 10223616K, used 5029872K [0x0000000570000000, 0x00000005720009c0, 0x00000007e0000000)
region size 32768K, 7 young (229376K), 7 survivors (229376K)
Metaspace used 112870K, capacity 115300K, committed 115968K, reserved 1150976K
class space used 12713K, capacity 13380K, committed 13568K, reserved 1048576K
}
[Times: user=0.45 sys=0.01, real=0.10 secs]
2023-06-03T14:40:31.493+0800: 184748.215: [GC concurrent-root-region-scan-start]
2023-06-03T14:40:31.528+0800: 184748.251: [GC concurrent-root-region-scan-end, 0.0359052 secs]
2023-06-03T14:40:31.528+0800: 184748.251: [GC concurrent-mark-start]
2023-06-03T14:40:31.623+0800: 184748.345: [GC concurrent-mark-end, 0.0942951 secs]
2023-06-03T14:40:31.624+0800: 184748.347: [GC remark 2023-06-03T14:40:31.624+0800: 184748.347: [Finalize Marking, 0.0003013 secs] 2023-06-03T14:40:31.625+0800: 184748.347: [GC ref-proc, 3.7471488 secs] 2023-06-03T14:40:35.372+0800: 184752.094: [Unloading, 0.0254883 secs], 3.7778434 secs]
[Times: user=3.88 sys=0.05, real=3.77 secs]
2023-06-03T14:40:35.404+0800: 184752.127: [GC cleanup 4943M->4879M(9984M), 0.0025357 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2023-06-03T14:40:35.407+0800: 184752.129: [GC concurrent-cleanup-start]
2023-06-03T14:40:35.407+0800: 184752.130: [GC concurrent-cleanup-end, 0.0000777 secs]
{Heap before GC invocations=409 (full 0):
garbage-first heap total 10223616K, used 6930416K [0x0000000570000000, 0x00000005720009c0, 0x00000007e0000000)
region size 32768K, 67 young (2195456K), 7 survivors (229376K)
Metaspace used 112870K, capacity 115300K, committed 115968K, reserved 1150976K
class space used 12713K, capacity 13380K, committed 13568K, reserved 1048576K
根据日志分析，该G1垃圾回收器共进行了一次youngGC 和 一次并发标记。
young GC在14:40:31.391开始，暂停时间为0.1017154秒，是 young collection 和 initial-mark 阶段。并且6个 GC 工作线程并行执行了70.3毫秒。GC 过程中，有多个阶段的时间记录和详细信息。堆大小从6521M减少到4912M。
并发标记在14:40:31.493开始，并涉及并发扫描、标记和重标记等阶段。在清理阶段结束后，堆大小从4943M减少到4879M。
因此，该 G1 垃圾回收器在这段时间STW（Stop-The-World）的总时间为 0.10 + 3.77 = 3.87 秒。
Gceasy.io 分析的结果：
疑问1：youngGC后堆内存回收不明显？
后面会追溯到MySQL的链接池虚引用，本次GC只能先将链接实例GC掉， 而用于追踪connection实例回收的虚引用，会在下次GC才能被回收。
疑问2：G1的MaxGCPauseMillis是否严格遵守，为什么我配置了-XX:MaxGCPauseMillis=100 本次gc时间还是达到了3秒以上？
G1 的 -XX:MaxGCPauseMillis 参数表示 G1 GC 的最大 STW 时间，即如果单次 GC 暂停时间超过该值，则 G1 会尽可能地调整其行为以达到该目标。但是请注意，该参数是一个指导性的参数，不能保证绝对精度。
在实际应用中，由于应用程序和系统的负载情况、堆内存大小等因素的影响，GC 的发生和 STW 时间都可能会出现一定程度的波动和不确定性。因此，单次 GC 暂停时间超过 -XX:MaxGCPauseMillis 配置值是有可能发生的，而且这种情况在高负载或堆内存使用较高时更容易出现。
疑问3：监控中为啥出现了多次mixed GC， 而且间隔还如此的短
-XX:G1MixedGCCountTarget，默认为8，这个参数标识最后的混合回收阶段会执行8次，一次只回收掉一部分的Region，然后系统继续运行，过一小段时间之后，又再次进行混合回收，重复8次。执行这种间断的混合回收，就可以把每次的混合回收时间控制在我们需要的停顿时间之内了，同时达到垃圾清理的效果。清理了 7 次就已经满足了回收效果，所以没有继续 mixed GC。
以上是为了：MaxGCPauseMillis 停顿时间控制在期望范围内，所以会出现多次间隔很短连续的mixed GC.
dump分析
通过 MAT 工具分析发现，第一个可能的问题就是：com.mysql.jdbc.NonRegisteringDriver 占用比较大的内存，如下图：
The class com.mysql.jdbc.NonRegisteringDriver, loaded by org.apache.catalina.loader.ParallelWebappClassLoader @ 0x73e8b9a00, occupies 857,532,208 (88.67%) bytes. The memory is accumulated in one instance of java.util.concurrent.ConcurrentHashMap$Node[], loaded by , which occupies 857,529,112 (88.67%) bytes.
Keywords
com.mysql.jdbc.NonRegisteringDriver
org.apache.catalina.loader.ParallelWebappClassLoader @ 0x73e8b9a00
java.util.concurrent.ConcurrentHashMap$Node[]
·然后看大对象列表，NonRegisteringDriver 对象确实占内存比较多，其中成员变量connectionPhantomRefs 占内存最多，里面存的是数据库连接的虚引用，其类型是 ConcurrentHashMap，占比居然有88%之多。
增加JVM参数，打印详细对象回收扫描日志
增加JVM参数： -XX:+PrintReferenceGC， 打印各种引用对象的详细回收时间：
PrintReferenceGC是JVM提供的一个参数，用于在进行垃圾回收时打印引用处理相关信息。当启用该参数后，JVM会在每次进行垃圾回收时将一些有关引用处理（Reference Processing）的信息输出到标准输出或指定的日志文件中。
具体来说，PrintReferenceGC参数可帮助开发人员和系统管理员更好地了解应用程序中各种类型引用被处理的情况，包括Soft Reference、Weak Reference、Phantom Reference等。这些信息对于诊断内存泄漏和调整垃圾回收器性能非常有用。
打印的详细的gc日志如下：
2023-06-04T10:28:52.886+0800: 24397.548: [GC concurrent-root-region-scan-start]
2023-06-04T10:28:52.941+0800: 24397.602: [GC concurrent-root-region-scan-end, 0.0545027 secs]
2023-06-04T10:28:52.941+0800: 24397.602: [GC concurrent-mark-start]
2023-06-04T10:28:53.198+0800: 24397.859: [GC concurrent-mark-end, 0.2565503 secs]
2023-06-04T10:28:53.199+0800: 24397.860: [GC remark 2023-06-04T10:28:53.199+0800: 24397.860: [Finalize Marking, 0.0004169 secs] 2023-06-04T10:28:53.199+0800: 24397.861: [GC ref-proc2023-06-04T10:28:53.199+0800: 24397.861: [SoftReference, 9247 refs, 0.0035753 secs]2023-06-04T10:28:53.203+0800: 24397.864: [WeakReference, 963 refs, 0.0003121 secs]2023-06-04T10:28:53.203+0800: 24397.865: [FinalReference, 60971 refs, 0.0693649 secs]2023-06-04T10:28:53.273+0800: 24397.934: [PhantomReference, 49828 refs, 20 refs, 4.5339260 secs]2023-06-04T10:28:57.807+0800: 24402.468: [JNI Weak Reference, 0.0000755 secs], 4.6213645 secs] 2023-06-04T10:28:57.821+0800: 24402.482: [Unloading, 0.0332897 secs], 4.6620392 secs]
[Times: user=4.60 sys=0.31, real=4.67 secs]
2023-06-04T10:28:57.863+0800: 24402.524: [GC cleanup 4850M->4850M(9984M), 0.0031413 secs]
[Times: user=0.01 sys=0.01, real=0.00 secs]
{Heap before GC invocations=68 (full 0):
garbage-first heap total 10223616K, used 7883923K [0x0000000570000000, 0x00000005720009c0, 0x00000007e0000000)
region size 32768K, 98 young (3211264K), 8 survivors (262144K)
Metaspace used 111742K, capacity 114304K, committed 114944K, reserved 1150976K
class space used 12694K, capacity 13362K, committed 13568K, reserved 1048576K
翻译日志内容如下：
2023-06-04T10:28:52.886+0800: 24397.548: [GC concurrent-root-region-scan-start]：开始扫描并发根区域。
2023-06-04T10:28:52.941+0800: 24397.602: [GC concurrent-root-region-scan-end, 0.0545027 secs]：并发根区域扫描结束，持续时间为0.0545027秒。
2023-06-04T10:28:52.941+0800: 24397.602: [GC concurrent-mark-start]：开始并发标记过程。
2023-06-04T10:28:53.198+0800: 24397.859: [GC concurrent-mark-end, 0.2565503 secs]：并发标记过程结束，持续时间为0.2565503秒。
2023-06-04T10:28:53.199+0800: 24397.860: [GC remark]: G1执行remark阶段。
2023-06-04T10:28:53.199+0800: 24397.860: [Finalize Marking, 0.0004169 secs]：标记finalize队列中待处理对象，持续时间为0.0004169秒。
2023-06-04T10:28:53.199+0800: 24397.861: [GC ref-proc]: 进行引用处理。
2023-06-04T10:28:53.199+0800: 24397.861: [SoftReference, 9247 refs, 0.0035753 secs]：处理软引用，持续时间为0.0035753秒。
2023-06-04T10:28:53.203+0800: 24397.864: [WeakReference, 963 refs, 0.0003121 secs]：处理弱引用，持续时间为0.0003121秒。
2023-06-04T10:28:53.203+0800: 24397.865: [FinalReference, 60971 refs, 0.0693649 secs]：处理虚引用，持续时间为0.0693649秒。
2023-06-04T10:28:53.273+0800: 24397.934: [PhantomReference, 49828 refs, 20 refs, 4.5339260 secs]：处理final reference中的phantom引用，持续时间为4.5339260秒。
2023-06-04T10:28:57.807+0800: 24402.468: [JNI Weak Reference, 0.0000755 secs]：处理JNI weak引用，持续时间为0.0000755秒。
2023-06-04T10:28:57.821+0800: 24402.482: [Unloading, 0.0332897 secs]：卸载无用的类，持续时间为0.0332897秒。
[Times: user=4.60 sys=0.31, real=4.67 secs]：垃圾回收的时间信息，user表示用户态CPU时间、sys表示内核态CPU时间、real表示实际运行时间。
2023-06-04T10:28:57.863+0800: 24402.524: [GC cleanup 4850M->4850M(9984M), 0.0031413 secs]：执行cleanup操作，将堆大小从4850M调整为4850M，持续时间为0.0031413秒。
其中PhantomReference耗时最长：
2023-06-04T10:28:53.273+0800: 24397.934: [PhantomReference, 49828 refs, 20 refs, 4.5339260 secs]：处理final reference中的phantom引用，持续时间为4.5339260秒。
源码追踪
MYSQL driver相关
注意，本源码基于当前依赖的mysql-connector-java-5.1.30.jar, 各版本的代码有一定差异性质;
涉及MySQL创建连接池的地方为：com.mysql.jdbc.NonRegisteringDriver#connect方法:
public Connection connect(String url, Properties info) throws SQLException {
//...省略部分代码
Properties props = null;
if ((props = this.parseURL(url, info)) == null) {
return null;
} else if (!"1".equals(props.getProperty("NUM_HOSTS"))) {
return this.connectFailover(url, info);
} else {
try {
// 获取连接主要在这里
com.mysql.jdbc.Connection newConn = ConnectionImpl.getInstance(this.host(props), this.port(props), props, this.database(props), url);
return newConn;
} catch (SQLException var6) {
throw var6;
} catch (Exception var7) {
SQLException sqlEx = SQLError.createSQLException(Messages.getString("NonRegisteringDriver.17") + var7.toString() + Messages.getString("NonRegisteringDriver.18"), "08001", (ExceptionInterceptor)null);
sqlEx.initCause(var7);
throw sqlEx;
}
}
}
com.mysql.jdbc.ConnectionImpl构造器比较长，在完成参数构建后，在其结尾处，发现它调用了NonRegisteringDriver.trackConnection(this)。
public ConnectionImpl(String hostToConnectTo, int portToConnectTo, Properties info, String databaseToConnectTo, String url) throws SQLException {
......
NonRegisteringDriver.trackConnection(this);
}
其中追踪任务的注册如下：这段MySQL driver源码的作用是实现对MySQL数据库连接的跟踪。
public class NonRegisteringDriver {
//省略部分代码...
// 连接虚引用指向map的容器声明
protected static final ConcurrentHashMap connectionPhantomRefs = new ConcurrentHashMap();
// 将连接放入追踪容器中
protected static void trackConnection(com.mysql.jdbc.Connection newConn) {
ConnectionPhantomReference phantomRef = new ConnectionPhantomReference((ConnectionImpl)newConn, refQueue);
connectionPhantomRefs.put(phantomRef, phantomRef);
}
//省略部分代码...
}
第一行代码声明了一个名为connectionPhantomRefs的ConcurrentHashMap容器，该容器用于存储ConnectionPhantomReference实例。
第二个方法trackConnection的作用是将新连接添加到connectionPhantomRefs映射中。它接受一个com.mysql.jdbc.Connection对象作为参数，创建一个新的ConnectionPhantomReference实例，并使用它和引用队列（refQueue）将其添加到connectionPhantomRefs映射中。
总的来说，这两个代码片段旨在通过使用虚引用来实现跟踪连接到MySQL数据库的机制。虚引用用于跟踪已被JVM垃圾回收的对象，允许程序在对象从内存中删除后执行特定任务。
连接虚引用为静态内部类
这段代码是 MySQL 驱动程序的一部分，用于清理底层网络资源并确保在 MySQL 连接对象被垃圾回收时释放这些资源。
static class ConnectionPhantomReference extends PhantomReference {
private NetworkResources io;
ConnectionPhantomReference(ConnectionImpl connectionImpl, ReferenceQueue q) {
super(connectionImpl, q);
try {
this.io = connectionImpl.getIO().getNetworkResources();
} catch (SQLException var4) {
}
}
void cleanup() {
if (this.io != null) {
try {
this.io.forceClose();
} finally {
this.io = null;
}
}
}
}
这段 MySQL driver 源码中的 ConnectionPhantomReference 类是一个继承自 PhantomReference 的静态内部类，其中 ConnectionImpl 是 MySQL 连接的实现类。该类的作用是在连接对象被垃圾回收时清理底层网络资源。
ConnectionPhantomReference 构造函数接受 ConnectionImpl 对象和一个引用队列作为参数，并调用父类 PhantomReference 的构造函数来创建虚引用。它还通过调用 ConnectionImpl 的 getIO().getNetworkResources() 方法获取与连接关联的网络资源。如果获取失败，则不会抛出异常。
cleanup() 方法用于在连接对象被垃圾回收后清理网络资源。它检查 io 属性是否为空，如果不为空，则调用 forceClose() 方法来强制关闭底层网络资源，最终将 io 属性设置为 null。整个过程确保连接对象被垃圾回收时，底层网络资源也被正确地释放。
MySQL为什么要使用虚引用来解决IO资源回收问题？
MySQL 使用虚引用来解决 IO 资源回收问题，主要是因为 JDBC 连接对象在关闭连接时无法保证其底层网络资源会被立即释放。这可能会导致底层网络资源长时间占用，最终导致应用程序出现性能下降或者资源耗尽的情况。
使用虚引用的好处在于，它允许程序在对象从内存中删除后执行特定任务。 MySQL 驱动程序利用 Java 提供的引用队列机制，将 JDBC 连接对象的虚引用加入到队列中。一旦连接对象被垃圾回收，JVM 会将它加入到引用队列中等待进一步处理。此时，MySQL 驱动程序通过监视引用队列并清理底层网络资源，确保这些资源在连接对象被垃圾回收时被正确地释放，从而避免了底层网络资源长时间占用的问题。
使用虚引用的优点在于可以实现更精细的内存管理和资源回收，提高应用程序的可靠性和性能。
那MySQL是怎样执行最终的IO资源回收的呢，是使用了定时任务还是异步守护线程？
MySQL 在执行最终的 IO 资源回收时，使用了异步守护线程来清理底层网络资源。
MySQL 驱动程序将 JDBC 连接对象的虚引用加入到引用队列中后，会创建一个专门的守护线程来监视该引用队列。当连接对象被垃圾回收并加入到引用队列中后，守护线程会从引用队列中获取该连接对象的虚引用，并在后台线程中执行与连接相关的底层网络资源清理工作。
具体来说，守护线程在每次迭代中从引用队列中获取一组虚引用，并调用虚引用的 cleanup() 方法来清理底层网络资源。如果成功清理，则将其从映射表中删除；否则，保留虚引用以便下一次迭代。
由于清理操作是在后台线程中进行的，因此不会阻塞应用程序的主线程。同时，使用异步守护线程还可以避免定时任务可能带来的性能开销和不必要的 CPU 使用率。
MySQL 使用异步守护线程来执行 IO 资源回收工作，这种方式可以确保底层网络资源的及时释放，并且不会对应用程序的性能产生负面影响。
以下是 MySQL 驱动程序中执行 IO 资源回收的守护线程的相关代码：
public class NonRegisteringDriver implements java.sql.Driver {
//省略代码...
//在MySQL driver中守护线程创建及启动...
static {
AbandonedConnectionCleanupThread referenceThread = new AbandonedConnectionCleanupThread();
referenceThread.setDaemon(true);
referenceThread.start();
}
//省略代码...
}
public class AbandonedConnectionCleanupThread extends Thread {
private static boolean running = true;
private static Thread threadRef = null;
public AbandonedConnectionCleanupThread() {
super("Abandoned connection cleanup thread");
}
public void run() {
threadRef = this;
while (running) {
try {
Reference
