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<ConnectionPhantomReference, ConnectionPhantomReference>，占比居然有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<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);
}
//省略部分代碼...
}
第一行代碼宣告了一個名為connectionPhantomRefs的ConcurrentHashMap容器，該容器用于存盤ConnectionPhantomReference實體，
第二個方法trackConnection的作用是將新連接添加到connectionPhantomRefs映射中，它接受一個com.mysql.jdbc.Connection物件作為引數，創建一個新的ConnectionPhantomReference實體，并使用它和參考佇列（refQueue）將其添加到connectionPhantomRefs映射中，
總的來說，這兩個代碼片段旨在通過使用虛參考來實作跟蹤連接到MySQL資料庫的機制，虛參考用于跟蹤已被JVM垃圾回收的物件，允許程式在物件從記憶體中洗掉后執行特定任務，
連接虛參考為靜態內部類
這段代碼是 MySQL 驅動程式的一部分，用于清理底層網路資源并確保在 MySQL 連接物件被垃圾回收時釋放這些資源，
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;
}
}
}
}
這段 MySQL driver 原始碼中的 ConnectionPhantomReference 類是一個繼承自 PhantomReference<ConnectionImpl> 的靜態內部類，其中 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<? 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;
}
}
}
這段代碼是 MySQL 驅動程式中的一個類 AbandonedConnectionCleanupThread，該類繼承自 Java 的 Thread 類，其作用是定期清理連接物件的底層網路資源，防止出現資源泄露和記憶體溢位等問題，在該類的 run() 方法中，回圈檢查是否有虛參考需要清理，如果存在，則呼叫 cleanup() 方法來清理虛參考所關聯的底層網路資源，并從 NonRegisteringDriver.connectionPhantomRefs 映射中洗掉該虛參考，
在 MySQL 驅動程式中，connectionPhantomRefs 映射表的鍵和值都是 ConnectionPhantomReference 型別的物件，即使用同一個物件作為鍵和值，
這樣做的主要原因是，在虛參考被加入到參考佇列中時，需要從映射表中洗掉對應的虛參考，如果將虛參考物件作為鍵，那么在洗掉虛參考時，需要遍歷整個映射表才能找到該虛參考物件并將其洗掉，這會造成不必要的性能開銷，
相反，如果將虛參考物件作為值，那么只需要使用該虛參考物件自身來洗掉映射表中的條目，就可以提高洗掉效率，在 trackConnection() 方法中，創建一個新的 ConnectionPhantomReference 物件，并將其作為鍵和值存盤到 connectionPhantomRefs 映射表中，這樣，在虛參考被加入到參考佇列中時，只需從映射表中洗掉該虛參考物件自身即可，無需遍歷整個映射表，
總之，使用同一個物件作為映射表的鍵和值，可以更有效地洗掉映射表中的條目，提高性能和效率，
PS: java.lang.ref.ReferenceQueue#remove(long) 介紹
java.lang.ref.ReferenceQueue#remove(long) 方法的作用是從佇列中移除已經被回收的 Reference 物件，若佇列中沒有任何元素，則該方法會一直等待直到有元素加入或者經過指定時間后回傳 null，
該方法的引數為超時時間，單位為毫秒，如果在指定的超時時間內沒有元素加入佇列，則該方法回傳 null，如果超時時間為 0，則該方法立即回傳，并且不會等待任何元素加入佇列，
通常情況下，程式不需要呼叫這個方法，Java 虛擬機會自動呼叫該方法來處理已經被回收的物件，只有在特定的情況下，如手動管理記憶體時才需要手動呼叫該方法，
這里使用java.lang.ref.ReferenceQueue主要作用是在Connection被垃圾回收器回收后， 能通過remove(timeout) 獲取已經被回收的參考佇列，然后進行后置處理，
推斷
因為目前在NonRegisteringDriver的靜態成員變數：connectionPhantomRefs, 有幾萬個物件， 證明在這段時間積累了大量的資料庫鏈接connection實體進入以下生命周期：
創建 --> 閑置 ---> 回收;
疑點1：
因為前面連接閑置時間為db.minEvictableIdleTimeMillis=180000（3分鐘）， 可能是造成問題的關鍵，正常的MySQL鏈接閑置時間默認為8小時，
疑點2：
此外，因為該應用有多個資料源，且部分資料進行了分庫，導致和資料庫的連接數較多，而且訪問請求也不均勻，這就導致了高峰期創建大量資料庫連接池，低峰期又被回收，使com.mysql.jdbc.NonRegisteringDriver#connectionPhantomRefs 中的物件越來越多，而且大部分進入老年代，需要fullGC或者G1 的mixedGC才能進行回收，
4. 解決方案
方案1：調整JVM引數
雖然問題的根源是MySQL的鏈接失效，造成虛參考在gc的remark階段耗時較長，但是我們的G1引數配置也存在問題：其中引數1的調整是本次減少GC時間的關鍵，
引數1：ParallelRefProcEnabled （并行參考處理開啟）
經過核查應用確認為G1GC 引數配置不當，未開啟ParallelRefProcEnabled（并行參考處理）JDK8需要手動開啟，JDK9+已默認開啟， 導致G1 Final Remark階段使用單執行緒標記（G1混合GC的時候，STW約為2~3秒)；
解決方案：
開啟ParallelRefProcEnabled（并行參考處理）功能后，ParallelGCThreads=8 啟用8執行緒標記；
引數2：ParallelGCThreads （并行 GC 執行緒數）
ParallelGCThreads引數是一個用于指定G1垃圾回收器并行垃圾收集執行緒數的引數，與其他Java垃圾回收器不同，G1垃圾回收器可以同時執行多個垃圾回收執行緒來加速垃圾回收速度，
在Java 8中，默認情況下，G1垃圾回收器的ParallelGCThreads引數設定為與CPU核心數量相同的值，最大為8，如果您的機器有更多的CPU核心，則可以通過手動調整該引數來提高并行垃圾回收的效率，例如，如果您的機器有8個核心，則可以將ParallelGCThreads設定為8或更高的值，
需要注意的是，過高的ParallelGCThreads值可能會導致處理器爭用和背景關系切換，從而影回應用程式的性能，因此，在進行調整時，應根據機器規格和實際負載進行測驗和優化，以找到最佳引數配置，建議保持默認值，并在實測結果反饋之后再進行適當的調整，
另外，還可以使用-XX:+UseDynamicNumberOfGCThreads引數讓G1自動適配并行執行緒數，這樣，執行緒數量會根據系統負載自動增減，從而獲得更好的性能
解決方案：
機器為8核，最開始只配置了6C，故而將并行GC執行緒數量增加到8，或者不不配置，默認為核心數8；
引數3：G1MixedGCLiveThresholdPercent （G1混合垃圾回收器存活閾值百分比）
G1MixedGCLiveThresholdPercent是一個用于控制G1垃圾回收器混合垃圾回收的引數，它決定混合垃圾回收器在何時執行，這個值指某一個標記為old region的區域中存活物件百分達到此閾值后，會被G1 mixed GC回收處理；
如果將該值設定得太低，則可能導致頻繁的混合垃圾回收，從而影回應用程式的性能；如果將其設定得太高，則可能會導致老年代中的垃圾增加，造成堆記憶體占用過高，單次STW延長，
默認值： 85%;
解決方案：
因為前期設定為80， 本次調整為60 ， 雖然增加混合GC觸發的頻率，但是因為此時物件更少，需要消耗的時間也變短；
引數4： MaxTenuringThreshold （物件晉升到老年代的最大年齡）
MaxTenuringThreshold是一個用于控制物件在Survivor區域中存活的時間閾值的引數，它指定了物件在經過多少次Minor GC后可以晉升到老年代，具體來說，如果某個物件在Survivor區域中存活了足夠長的時間（即經過足夠多次的Minor GC），則會被移動到老年代中，
在Java 8中，默認情況下，MaxTenuringThreshold引數設定為15，即物件必須在Survivor區域中存活15次Minor GC才能晉升到老年代，如果將其設定為0，則表示所有的物件都可以在第一次Minor GC時晉升到老年代；如果將其設定為較大的值，則表示只有存活時間比較長的物件才能晉升到老年代，
需要注意的是，如果將MaxTenuringThreshold引數設定得過小，則可能導致頻繁的晉升和回收操作，從而影回應用程式的性能；如果將其設定得過大，則可能會導致Survivor區域中的空間不足，從而強制進行Full GC操作，同樣也會影回應用程式的性能，
建議在實際應用程式場景中進行測驗和優化，以找到最佳的MaxTenuringThreshold值，通常，該值應該設定在8-15之間，并且應根據應用程式的記憶體使用情況和GC日志進行調整，
解決方案：
因為前期設定為5， 本次調整為15 ，或者不需要配置，默認為15；
調整后的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: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
方案2： 優化MySQL的虛參考問題
調整連接池引數
在諸多連接池中，發現一個引數配置錯誤，有一個資料庫的db.minEvictableIdleTimeMillis=180000（3分鐘），適當調大連接的閑置時間到30Min；
將DBCP連接池引數minIdle調小，減少閑置執行緒的數量（在整個連接都不活躍的情況下），也可以起到一定作用；
但是這個方式，治標不治本， 因為虛參考還在一直產生，
優化MySQL driver虛參考
A. 反射暴力清理
虛參考往往做為一種兜底策略，避免用戶忘記釋放資源，引發記憶體泄露（在未使用連接池的如java初學者手擼的資料庫鏈接管理代碼往往是有用的），我們使用DBCP或其它池化技術已經會嚴謹處理資源的釋放，可以不采用兜底策略，直接洗掉中 connectionPhantomRefs 中的虛參考，使物件不可達，在 GC 時直接回收，從而減少 PhantomReference 的處理時間，
// 每兩小時清理 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);
以上代碼通過反射定時清理掉NonRegisteringDriver靜態變數connectionPhantomRefs，即信任DBCP在鏈接回收的時候，會自動嚴謹處理資源釋放，MySQL driver自帶的安全防護全部定時清空，相當于禁用此功能，
特別說明： A方案無安全性問題，可放心采納；
B. 升級MySQL jdbc driver到8.0.22+，開啟disableAbandonedConnectionCleanup
Oracle應該是接收了大量開發人員的反饋，意識到了此功能可能造成GC嚴重過長的問題，在高版本中已經可以通過配置選擇性關閉此非必要拖尾功能， mysql-connector-java 版本（8.0.22+）的代碼對資料庫連接的虛參考有新的處理方式，其增加了開關，可以手動關閉此功能，
其版本8.0.22介紹增加此引數即是為了解決JVM 虛參考相關問題，但是默認是未啟用，需要手動開啟：
https://dev.mysql.com/doc/relnotes/connector-j/8.0/en/news-8-0-22.html
When 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=true
? 或者在代碼里設定屬性：
System.setProperty(PropertyDefinitions.SYSP_disableAbandonedConnectionCleanup,"true");
當 com.mysql.cj.disableAbandonedConnectionCleanup=true 時，生成資料庫連接時就不會生成虛參考，對 GC 就沒有任何影響了，
是否升級MySQL的驅動版本，根據實際情況取舍，以上A/B方案都能解決該問題，
總結
G1引數調優總結
- 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垃圾回收器之程序及原理進行詳細分析，請參考其它文章進行理解；
附錄：Oracle官方JDK8 G1引數調優官方檔案
MySQL虛參考問題總結
- MySQL 鏈接驅動如果在8.0.22版本以下，只能通過反射主動清理此非必要拖尾功能（一般成熟的資料庫連接池功能都能安全釋放鏈接相關資源），
- MySQL驅動8.0.22+版本， 可以通過配置手動關閉此功能；
結果說明
經過以上調整后（MySQL的虛參考問題一并解決后），gc時間能較好的控制在100ms以內，平均耗時26ms， mixed gc頻率大幅度減少， 主要為youngGC，
參考資料
線上問題分析系列：資料庫連接池記憶體泄漏問題的分析和解決方案
com.mysql.jdbc.NonRegisteringDriver 記憶體泄漏
神燈-線上問題處理案例1：出乎意料的資料庫連接池
G1收集器詳解及調優
infoq-Tips for Tuning the Garbage First Garbage Collector
Java Garbage Collection handbook
PPPHUANG-JVM 優化踩坑記
PPPHUANG- MySQL 驅動中虛參考 GC 耗時優化與原始碼分析
作者：京東零售 張世彬
來源：京東云開發者社區
轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/556269.html
標籤：其他
下一篇：返回列表