G1垃圾回收参数调优及MySQL虚引用造成GC时间过长分析
京
交易研发 张世彬约 25 分钟
交易研发 张世彬约 25 分钟我方有一应用，偶尔会出现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=20initialSize=10maxIdle=10minIdle=5minEvictableIdleTimeMillis=180000timeBetweenEvictionRunsMillis=20000validationQuery=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。
查询本地日志，找到下游timeout的接口日志, 并找到相关IP为：11.#.#.201。
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 1150976Kclass 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 1150976Kclass space used 12713K, capacity 13380K, committed 13568K, reserved 1048576K
疑问3：监控中为啥出现了多次mixed GC， 而且间隔还如此的短
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.Keywordscom.mysql.jdbc.NonRegisteringDriverorg.apache.catalina.loader.ParallelWebappClassLoader @ 0x73e8b9a00java.util.concurrent.ConcurrentHashMap$Node[]
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 WeakReference, 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 1150976Kclass 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秒。
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;}}}
public ConnectionImpl(String hostToConnectTo, int portToConnectTo, Properties info, String databaseToConnectTo, String url) throws SQLException {......NonRegisteringDriver.trackConnection(this);}
public class NonRegisteringDriver {//省略部分代码...// 连接虚引用指向map的容器声明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);}//省略部分代码...}
static class ConnectionPhantomReference extends PhantomReference<ConnectionImpl> {private NetworkResources io;ConnectionPhantomReference(ConnectionImpl connectionImpl, ReferenceQueue<ConnectionImpl> 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;}}}}
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<? extends ConnectionImpl> ref = NonRegisteringDriver.refQueue.remove(100);if (ref != null) {try {((ConnectionPhantomReference) ref).cleanup();} finally {NonRegisteringDriver.connectionPhantomRefs.remove(ref);}}} catch (Exception ex) {// no where to really log this if we're static}}}public static void shutdown() throws InterruptedException {running = false;if (threadRef != null) {threadRef.interrupt();threadRef.join();threadRef = null;}}}
gc日志，最终分析得到了 GC时间超过3.7秒的监控结果，这也是问题的根源。
虽然问题的根源是MySQL的链接失效，造成虚引用在gc的remark阶段耗时较长。但是我们的G1参数配置也存在问题：其中参数1的调整是本次减少GC时间的关键。
参数1：ParallelRefProcEnabled （并行引用处理开启）
经过核查应用确认为G1GC 参数配置不当，未开启ParallelRefProcEnabled（并行引用处理）JDK8需要手动开启，JDK9+已默认开启。 导致G1 Final Remark阶段使用单线程标记（G1混合GC的时候，STW约为2~3秒)；
-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:SurvivorRatio=10 -XX:InitiatingHeapOccupancyPercent=45-XX:G1ReservePercent=20 -XX:G1MixedGCLiveThresholdPercent=60 -XX:MaxGCPauseMillis=100-XX:+ExplicitGCInvokesConcurrent -XX:+ParallelRefProcEnabled -XX:+PrintGCDetails-XX:+PrintGCDateStamps -XX:+PrintReferenceGC -XX:+PrintHeapAtGC -Xloggc:/export/Logs/app/tomcat7-gc.log
// 每两小时清理 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);
https://dev.mysql.com/doc/relnotes/connector-j/8.0/en/news-8-0-22.htmlWhen using Connector/J, the AbandonedConnectionCleanupThread thread can now be disabled completely by setting the new system property com.mysql.cj.disableAbandonedConnectionCleanup to true when configuring the JVM. The feature is for well-behaving applications that always close all connections they create. Thanks to Andrey Turbanov for contributing to the new feature. (Bug #30304764, Bug #96870)
java -jar app.jar -Dcom.mysql.cj.disableAbandonedConnectionCleanup=trueSystem.setProperty(PropertyDefinitions.SYSP_disableAbandonedConnectionCleanup,"true");ParallelGCThreads 主要为并发标记相关线程，其本身处理时候也会STW， 最好全部占用CPU内核，如机器为8核，则该值最好设置为8； ConcGCThreads 为并发标记线程数量，其标记的时候，业务线程可以不STW， 可以使用部分核心，剩余部分核心用于跑业务线程；我们这里配置为CPU核心数量的一半4； MaxGCPauseMillis 只是一个期望值（GC会尽可能保证），并不能严格遵守，尤其是在标记阶段，会受到堆内存对象数量的影响，故而不能太过依赖此值觉得STW的实际时间；如我方配置的100ms， 实际出现3~4秒的机会也比较多； ParallelRefProcEnabled 如果你搜索的各种资料提醒你这个开关是默认开启的，那你要特别注意了； JDK8版本此功能是默认关闭的，在JDK9+之后才是默认开启。故而JDK8需要手动开启，保险起见，无论什么版本都配置该值； G1垃圾回收器基本上不会出现fullGC, 在youngGC 和 mixedGC（mixedGC频次也不高）就完成了垃圾回收。如果出现了fullGC， 反而应该排查是否有异常。 本文未对G1垃圾回收器之过程及原理进行详细分析，请参考其它文章进行理解；
MySQL 链接驱动如果在8.0.22版本以下，只能通过反射主动清理此非必要拖尾功能（一般成熟的数据库连接池功能都能安全释放链接相关资源）。 MySQL驱动8.0.22+版本， 可以通过配置手动关闭此功能；
线上问题分析系列：数据库连接池内存泄漏问题的分析和解决方案
com.mysql.jdbc.NonRegisteringDriver 内存泄漏
神灯-线上问题处理案例1：出乎意料的数据库连接池
G1收集器详解及调优
infoq-Tips for Tuning the Garbage First Garbage Collector
Java Garbage Collection handbook
PPPHUANG-JVM 优化踩坑记
PPPHUANG- MySQL 驱动中虚引用 GC 耗时优化与源码分析