本文記錄了服務(wù) JVM 優(yōu)化的過程與思路，有對 JVM GC 原理以及對問題排查方向和工具的介紹，也有走彎路和踩坑，分享出來希望對大家有所幫助。

本文概要

• 服務(wù)異常和排查過程
• RPC 接口超時(shí)的排查方向
• 問題根因和解決方案
• JVM GC 原理與優(yōu)化過程
• 基礎(chǔ)工具簡要介紹與使用

嘗試

RPC 服務(wù)調(diào)用方反饋服務(wù)有時(shí)會有超時(shí)。

查看服務(wù)管理平臺發(fā)現(xiàn)有客戶端調(diào)用超時(shí)，調(diào)用方的超時(shí)時(shí)間設(shè)置為 1s。

image-20220628131542745.png

猜測1：JVM GC 時(shí)業(yè)務(wù)線程停頓，導(dǎo)致客戶端超時(shí)。

遂查看節(jié)點(diǎn)的內(nèi)存使用率，發(fā)現(xiàn)在有大量超時(shí)異常時(shí)，服務(wù)節(jié)點(diǎn)的內(nèi)存使用率并沒有明顯的變化。此時(shí)覺得應(yīng)該不是 GC 導(dǎo)致的問題。（埋下大坑）

image-20220628131855784.png

猜測2：RPC服務(wù) 請求處理線程太少，大量請求在隊(duì)列等待處理，導(dǎo)致客戶端超時(shí)。

查看 RPC 服務(wù)配置的線程為 128。

image-20220628134100784.png

查看服務(wù)排隊(duì)總量最大為 31，最大值為 2 ，且大量超時(shí)發(fā)生時(shí)沒有排隊(duì)的請求量。

image-20220628131602243.png

此時(shí)基本斷定不是請求排隊(duì)導(dǎo)致客戶端超時(shí)。

猜測3：批量調(diào)用接口時(shí)，所有請求都沒用命中緩存，導(dǎo)致客戶端超時(shí)。

服務(wù)處理請求時(shí)，如果沒有命中緩存會從 DB，Wtable，HTTP 獲取原始數(shù)據(jù)，然后逐個(gè)設(shè)置緩存，方便下次使用。每次設(shè)置緩存的方式如下：

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

獲取了每個(gè)原始數(shù)據(jù)后，挨個(gè)設(shè)置緩存，過期時(shí)間統(tǒng)一為 1 小時(shí)。一小時(shí)后這些緩存同時(shí)過期，過期后的請求就會再次獲取原始數(shù)據(jù)，導(dǎo)致請求響應(yīng)時(shí)間變長。

優(yōu)化如下：

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

同一批設(shè)置緩存的過期時(shí)間有一個(gè)隨機(jī)數(shù)誤差，讓這一批緩存數(shù)據(jù)不至于同時(shí)過期，部分緩存過期后的請求時(shí)間相比全部緩存過期就會變短。分散同時(shí)獲取原始數(shù)據(jù)的數(shù)量，降低延遲。

這一優(yōu)化上線后，查看監(jiān)控確實(shí)有效果，客戶端超時(shí)數(shù)量銳減。此時(shí)，眉頭舒展，覺得問題已經(jīng)解決。

image-20220628133804618.png

好景不長，沒過兩天，調(diào)用方同學(xué)反饋又有超時(shí)。

猜測4：數(shù)據(jù)庫連接池不夠用，需要 DB 操作時(shí)等待連接，導(dǎo)致客戶端超時(shí)。

通過 trace 平臺查看請求的調(diào)用鏈：

image-20220628132334472.png

發(fā)現(xiàn)在一個(gè)請求調(diào)用鏈中有出現(xiàn)大量的 Wtable 和 Redis 的 get 或者 set 操作，有的高達(dá)上百個(gè)。按每個(gè) wtable、redis 的操作 1ms 算，那加起來也有上百毫秒。查看代碼發(fā)現(xiàn)部分接口在循環(huán)里獲取、設(shè)置緩存。但是這種情況不至于導(dǎo)致接口超時(shí)，所以沒有立即著手優(yōu)化。（盡量不要為了方便，在循環(huán)里有任何 IO 操作，最好批量 IO）

image-20220628133428760.png

在有些慢請求中發(fā)現(xiàn) MySQL 操作占用了時(shí)間線的絕大部分，懷疑可能有慢查詢。但是查看數(shù)據(jù)庫平臺發(fā)現(xiàn)超時(shí)時(shí)刻并沒有慢查詢。

image-20220628134509270.png

這時(shí)大膽懷疑起了 MySQL 的連接池不夠（連接池最大連接數(shù)設(shè)置為 30），有需要操作 DB 時(shí)等待獲取連接，導(dǎo)致 trace 統(tǒng)計(jì) MySQL 操作時(shí)間長但是又沒有慢查詢的問題。很河貍。

為了方便觀察連接池的狀態(tài)，在服務(wù)增加了連接池監(jiān)控，包含連接數(shù)量，活躍數(shù)量，空閑數(shù)量以及等待連接的數(shù)量，監(jiān)控內(nèi)容如下圖所示：

image-20220628131948333.png

image-20220628132010319.png

查看連接池監(jiān)控，在有客戶端超時(shí)時(shí)，總的連接數(shù)量最高為 14，并沒有超過設(shè)定的 30，等待獲取連接的也基本沒有，說明我們猜測連接池不夠?qū)е鲁瑫r(shí)的設(shè)想也不成立。

一頓操作猛如虎，一看戰(zhàn)績零杠五，心態(tài)已經(jīng)爆炸。

水落石出

沒有其他排查方向，重新懷疑最先排除的 GC 問題。

服務(wù)節(jié)點(diǎn)的配置是 8C16G，服務(wù)使用的垃圾收集器為 CMS，堆內(nèi)存為 12G。

因?yàn)闆]有輸出 GC 日志，只能通過 jstat 簡單查看 GC 情況，準(zhǔn)備修改 JVM 參數(shù)，輸出詳細(xì) GC 日志時(shí)，在監(jiān)控平臺發(fā)現(xiàn)了詳細(xì)的 JVM 監(jiān)控：

image-20220628131734531.png

image-20220628131801507.png

在 11 點(diǎn)鐘 FGC 的時(shí)間接近 4s，老年代使用率從 80% 降到 20% 多。堆內(nèi)存為 12G，新生代配置 4G，老年代為 8G，意味著回收近 4.8G 老年代內(nèi)存耗時(shí) 4s。此時(shí)這個(gè)節(jié)點(diǎn)有客戶端超時(shí)的情況。

為什么 FGC 的時(shí)間會突然這么長？五月下旬發(fā)現(xiàn)容器的內(nèi)存有 16G 但堆內(nèi)存只配了 8G，所以將堆內(nèi)存調(diào)整為 12G。從歷史監(jiān)控?cái)?shù)據(jù)可以看到調(diào)整之前每天一次 FGC 的頻率，變成每 1.7 天一次，F(xiàn)GC 的時(shí)間 1s 增加到 3s。

因?yàn)槎褍?nèi)存較大，CMS 比較適合小內(nèi)存的 JVM，大內(nèi)存時(shí)在 FGC 需要回收較多對象時(shí)會造成長時(shí)間停頓。

目前在小內(nèi)存應(yīng)用上 CMS 的表現(xiàn)大概率仍然要會優(yōu)于 G1，而在大內(nèi)存應(yīng)用上 G1 則大多能發(fā)揮其優(yōu)勢，這個(gè)優(yōu)劣勢的 Java 堆容量平衡點(diǎn)通常在 6GB 至 8GB 之間，當(dāng)然，以上這些也僅是經(jīng)驗(yàn)之談，不同應(yīng)用需要量體裁衣地實(shí)際測試才能得出最合適的結(jié)論，隨著 HotSpot 的開發(fā)者對 G1 的不斷優(yōu)化，也會讓對比結(jié)果繼續(xù)向 G1 傾斜?！渡钊肜斫釰ava虛擬機(jī)》

所以沒有優(yōu)化 CMS FGC 的耗時(shí)直接將垃圾收集器調(diào)整為 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

觀察三天發(fā)現(xiàn)問題解決，沒有 FGC, YGC 頻率降低，GC time下降：

image-20220701101502416.png

image-20220701101529611.png

image-20220701101551647.png

G1 GC 優(yōu)化

正當(dāng)我截出上面三張圖時(shí)，傳來噩耗，又出現(xiàn)大量超時(shí)，查看 GC 日志：

//初始標(biāo)記階段 - 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]

//并發(fā)標(biāo)記階段 - 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]

//最終標(biāo)記階段 - 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后，新生代擴(kuò)容
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] 

這次的日志可以總結(jié)出下面幾個(gè)問題：

為什么發(fā)生 mixed GC ？

當(dāng)達(dá)到 IHOP 閾值，-XX:InitiatingHeapOccupancyPercent（默認(rèn)45%）時(shí)，老年代使用內(nèi)存占到堆總大小的 45% 的時(shí)候，G1 將開始并發(fā)標(biāo)記階段 + Mixed GC。

GC 日志可以看到初始標(biāo)記時(shí)老年代大概 5500.9M，堆內(nèi)存 12G，5500 / 12000 ≈ 45.8%。

為什么 GC ref-proc 耗時(shí)這么長？

ref-proc 其實(shí)是對各種軟弱虛引用等的處理。

日志中 ref-proc 4.9682204s 就是處理 soft、weak、phantom、final、JNI 等等引用的時(shí)間。

初步懷疑是 softReference 或者是 finalReference 導(dǎo)致耗時(shí)較長。

為什么新生代 5484.0M 變?yōu)?576.0M？

remark 階段的耗時(shí)較長，導(dǎo)致 G1 新生代自適應(yīng)策略認(rèn)為需要盡可能的調(diào)小新生代大小，以滿足 200ms 的期望停頓時(shí)間，但是新生代最小值 -XX:G1NewSizePercent 在未配置的情況下為 5%，大概為 12G * 5% = 600M 左右。

為什么連續(xù) 6 次 mixed GC？

-XX:G1MixedGCCountTarget，默認(rèn)為8，這個(gè)參數(shù)標(biāo)識最后的混合回收階段會執(zhí)行8次，一次只回收掉一部分的Region，然后系統(tǒng)繼續(xù)運(yùn)行，過一小段時(shí)間之后，又再次進(jìn)行混合回收，重復(fù)8次。執(zhí)行這種間斷的混合回收，就可以把每次的混合回收時(shí)間控制在我們需要的停頓時(shí)間之內(nèi)了，同時(shí)達(dá)到垃圾清理的效果。

清理了 6 次就已經(jīng)滿足了回收效果，所以沒有繼續(xù) mixed GC。

為什么新生代 584.0M 變?yōu)?7028.0M？

mixed GC 之后的 YGC 耗時(shí)與期望停頓時(shí)間之間還有較大距離，所以 G1 新生代自適應(yīng)策略認(rèn)為加大新生代空間也能滿足期望停頓時(shí)間，并能減少 YGC 的頻率，所以增加了新生代的大小。

這么分析下來發(fā)現(xiàn)這一系列的問題都是因?yàn)?GC ref-proc 耗時(shí)較長導(dǎo)致的，然后在 G1 官網(wǎng)發(fā)現(xiàn)如下建議：

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.

大意為默認(rèn)情況 ref-proc 階段是單線程執(zhí)行的，若該階段耗時(shí)較長，可以添加 -XX:+ParallelRefProcEnabled 參數(shù)，盡量在該階段使用多線程處理，在添加該參數(shù)的基礎(chǔ)上，我們還新增了 -XX:+PrintReferenceGC ，方便在日志中看到 ref-proc 階段中的耗時(shí)詳情：

-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 參數(shù)后，ref-proc 階段耗時(shí)共為 0.6448878s，較 4.9682204s 有了巨大提升，雖然沒有超時(shí)出現(xiàn)，但還是較長，不能容忍，需要繼續(xù)優(yōu)化。

ref-proc 階段主要耗時(shí)在處理 PhantomReference 上，共耗時(shí) 0.64s。

PhantomReference 是什么？

• 虛引用也稱為“幽靈引用”，它是最弱的一種引用關(guān)系。
• 如果一個(gè)對象僅持有虛引用，那么它就和沒有任何引用一樣，在任何時(shí)候都可能被垃圾回收器回收。
• 為一個(gè)對象設(shè)置虛引用關(guān)聯(lián)的唯一目的只是為了能在這個(gè)對象被收集器回收時(shí)收到一個(gè)系統(tǒng)通知。
• 當(dāng)垃圾回收器準(zhǔn)備回收一個(gè)對象時(shí)，如果發(fā)現(xiàn)它還有虛引用，就會在垃圾回收后，將這個(gè)虛引用加入引用隊(duì)列，在其關(guān)聯(lián)的虛引用出隊(duì)前，不會徹底銷毀該對象。所以可以通過檢查引用隊(duì)列中是否有相應(yīng)的虛引用來判斷對象是否已經(jīng)被回收了。

大概了解了一點(diǎn) PhantomReference 是什么之后，為了搞清楚 PhantomReference 類型的到底是哪些對象，我們查看堆文件中的對象分布，發(fā)現(xiàn) PhantomReference 類型大部分都是這個(gè)類 com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference，有2439個(gè)。（dump 文件時(shí)務(wù)必摘除該節(jié)點(diǎn)的流量，否則影響線上請求）

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

ConnectionPhantomReference 是什么對象？

在 MySql jdbc 驅(qū)動代碼中發(fā)現(xiàn)，NonRegisteringDriver 類有個(gè)虛引用集合 connectionPhantomRefs 用于存儲所有的數(shù)據(jù)庫連接，NonRegisteringDriver.trackConnection 方法負(fù)責(zé)把新創(chuàng)建的連接放入 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 連接池有個(gè) maxLifeTime 配置項(xiàng)，意思為連接的最長存活時(shí)間，超過該時(shí)間則回收該連接，然后生成新連接。我們的配置中沒有設(shè)置該值，源碼中默認(rèn)為 30 分鐘，意味著我們生成的連接最多使用 30 分鐘。

// HikariCP maxLifeTime 默認(rèn)值
MAX_LIFETIME = TimeUnit.MINUTES.toMillis(30L);

因此我們雖使用了連接池，也會不斷的創(chuàng)建新連接。新的連接不斷增加 NonRegisteringDriver 類中虛引用集合 connectionPhantomRefs的虛引用數(shù)量，累計(jì)一定數(shù)量之后增加 ref-proc 的耗時(shí)。

問題定位了，我們只能減少虛引用集合中的虛引用數(shù)量，也就是減少生成新連接的速度，最大限度使用有效連接。

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 的值比數(shù)據(jù)庫的 wait_timeout 值少幾分鐘為好。

我們 MySql 的 wait_timeout 默認(rèn)為 3600 秒，所以將 maxLifeTime 設(shè)置為59分鐘，同時(shí)將空閑連接的存活時(shí)間調(diào)整為 30 分鐘，最大限度的減少新連接的生成。

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

連接池優(yōu)化上線 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] 

雖然我們調(diào)長了連接池連接的生命時(shí)長，但是這次上線 3.5 天才發(fā)生 mixed GC，積累的連接虛引用還是沒怎么變少，有 2000 多個(gè)，ref-proc 階段的耗時(shí)依舊長達(dá) 0.6473847s。

因?yàn)?MySql 的 wait_timeout 值為 3600 秒，maxLifeTime 的值也無法超過一個(gè)小時(shí)，所以 ref-proc 耗時(shí)仍不理想，會導(dǎo)致 G1 將新生代調(diào)整的較小，連續(xù)觸發(fā) GC。

大力出奇跡

虛引用往往做為一種兜底策略，避免用戶忘記釋放資源，引發(fā)內(nèi)存泄露。我們使用連接池會嚴(yán)謹(jǐn)處理資源的釋放，可以不采用兜底策略，直接刪除中 connectionPhantomRefs 中的虛引用，使對象不可達(dá)，在 GC 時(shí)直接回收，從而減少 PhantomReference 的處理時(shí)間。

使用定時(shí)任務(wù)清理 connectionPhantomRefs：

// 每兩小時(shí)清理 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);

定時(shí)清理 connectionPhantomRefs 的操作在某種程度上來說還是有點(diǎn)暴力，保險(xiǎn)起見我們在測試平臺進(jìn)行了幾天的穩(wěn)定性測試，沒有什么問題后再上線。

3.5 天后迎來喜訊， YGC 耗時(shí) 20 毫秒左右，mixed GC 耗時(shí) 10-40 毫秒左右，ref-proc 階段耗時(shí)共為 10 毫秒，PhantomReference 階段耗時(shí) 0.5 毫秒，符合預(yù)期：

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] 

老年代使用比例圖：

image-20220712100831013.png

YGC 次數(shù)圖：

image-20220712100857949.png

YGC 耗時(shí)圖：

image-20220712100915928.png

mixed GC 后老年代 85% 到 20%；一分鐘內(nèi)發(fā)生 7 次 YGC 或者 mixed GC，共耗時(shí) 126 毫秒，平均每次 18 毫秒，完全符合我們的停頓要求。 雖然 mixed GC 的耗時(shí)已經(jīng)降低，但是發(fā)現(xiàn) G1 還是會將新生代降到最小，也就是堆的 5%，可能會在后續(xù)的幾十秒內(nèi)每兩秒一次 GC（每次耗時(shí) 10-40 毫秒)，如果你覺得不能忍受的話，可以通過 -XX:G1NewSizePercent 來控制最小新生代的大小。

服務(wù)的 GC 時(shí)長由原來的 CMS FGC 4s 到現(xiàn)在 G1 mixed GC 10-40ms，也沒有因?yàn)?GC 導(dǎo)致的超時(shí)問題了，至此服務(wù)的 GC 優(yōu)化告一段落，但是后續(xù)還需要對業(yè)務(wù)導(dǎo)致的超時(shí)進(jìn)行優(yōu)化。

G1 YGC 異常耗時(shí)探究

后續(xù)觀察 JVM 監(jiān)控時(shí)發(fā)現(xiàn)有個(gè)節(jié)點(diǎn)的 YGC 時(shí)間異常，正常都是幾十毫秒，但這次高達(dá) 250 毫秒（MaxGCPauseMillis=200）：

image-20220629174536688.png

查看該節(jié)點(diǎn)的 GC 日志，

正常耗時(shí)的 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]

異常耗時(shí)的 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 毫秒，對比發(fā)現(xiàn)如下異常：

//正常
[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) ：內(nèi)存回收過程中將存活對象遷移到新的 region 和 survivor，也有一部分會晉升到老年代region，對象拷貝的時(shí)間。Min 為多線程回收中最少的耗時(shí)，Avg 為平均耗時(shí)，Max 為最大耗時(shí)，Diff 為拷貝對象耗時(shí)最大差值，Sum 為所有 GC 線程拷貝對象的時(shí)間總和。

Termination (ms) ：GC 工作線程終止時(shí)間。Min 為線程終止最少的耗時(shí)，Avg 為平均耗時(shí)，Max 為最大耗時(shí)，Diff 為耗時(shí)最大差值，Sum 為所有 GC 線程終止耗時(shí)的總和。

user ：JVM 代碼耗時(shí)。

sys：操作系統(tǒng)耗時(shí)。

real：業(yè)務(wù)線程停頓耗時(shí)。

日志異同

可以看到異常日志中 Termination 時(shí)間很高，最大耗時(shí) 211 毫秒，但是正常的 GC 日志中 Termination 耗時(shí)都是 0。

異常日志中的 Object Copy 時(shí)間較高，最少 5.8 毫秒，最大 216 毫秒，差值高達(dá) 211 毫秒。但是在正常日志中 Object Copy 時(shí)間比較平均，都為幾毫秒。

異常情況下操作系統(tǒng)耗時(shí) sys = 0.27 比正常 sys = 0.03，高了 9 倍。

初步分析是某個(gè)線程在拷貝對象時(shí)有些異常，導(dǎo)致 Termination 時(shí)間長。所以根因是 Object Copy 時(shí)間。

假設(shè) 8 個(gè) GC 線程中有一個(gè)異常（配置 GC Workers: 8），最大耗時(shí)為 211 毫秒，另七個(gè)線程為正常 GC 線程的平均耗時(shí)6.5毫秒，那計(jì)算平均耗時(shí)為：

(6.5 * 7 + 211) / 8 = 32.0625，與異常日志中的 Avg: 32.3 基本一致，印證了有一個(gè) GC 線程異常的猜想。

為何異常

查了很多資料沒有確切答案，但在 stackoverflow 找到一個(gè)貌似可能的答案：

swap activity or transparent huge pages are likely suspects.

關(guān)于操作系統(tǒng)耗時(shí)較多：

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.

意思可能是交換內(nèi)存或者Transparent Huge Pages (THP) 導(dǎo)致內(nèi)存操作耗時(shí)較長。

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

image-20220629142714275.png

always madvise [never] 表明禁用。

查看容器磁盤 IO 監(jiān)控：

image-20220629192155390.png

發(fā)現(xiàn)異常 YGC 時(shí)間附近確實(shí)有大量的 IO 操作記錄。有可能與交換內(nèi)存有關(guān)。

目前只發(fā)現(xiàn)少數(shù)異常 YGC 耗時(shí)的記錄，能力有限沒有繼續(xù)深究根本問題，暫且定位為虛擬運(yùn)行環(huán)境導(dǎo)致系統(tǒng)操作耗時(shí)較長導(dǎo)致的問題，有大佬了解可以指點(diǎn)指點(diǎn)。

總結(jié)

JVM 啟動后會逐步申請至最大堆內(nèi)存，GC 只將內(nèi)存清理，并不會釋放給系統(tǒng)，所以 FGC 時(shí)在節(jié)點(diǎn)的內(nèi)存使用率上看不到內(nèi)存波動。內(nèi)存使用率圖表導(dǎo)致了錯(cuò)誤的判斷，錯(cuò)失第一時(shí)間發(fā)現(xiàn)問題的機(jī)會。好在此次排查過程增加了類似問題的排查經(jīng)驗(yàn)，暴露了一些問題，也增加了數(shù)據(jù)庫連接池的監(jiān)控。

參考

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

從一起GC血案談到反射原理

一次簡單的G1GC參數(shù)調(diào)優(yōu)

新生代自適應(yīng)策略

PhantomReference 引發(fā)的GC問題

數(shù)據(jù)庫連接池內(nèi)存泄漏問題的分析和解決方案

一位后端寫碼師，一位黑暗料理制造者。公眾號：DailyHappy