最近，我們系統(tǒng)配置了GC耗時的監(jiān)控，但配置上之后，系統(tǒng)會偶爾出現(xiàn)GC耗時大于1s的報警，排查花了一些力氣，故在這里分享下。

我們系統(tǒng)分多個環(huán)境部署，出現(xiàn)GC長耗時的是俄羅斯環(huán)境，其它環(huán)境沒有這個問題，這里比較奇怪的是，俄羅斯環(huán)境是流量最低的一個環(huán)境，而且大多數(shù)GC長耗時發(fā)生在深夜。

發(fā)現(xiàn)報警后，我立馬查看了GC日志，如下： 

日志中出現(xiàn)了to-space exhausted，經(jīng)過一番了解，出現(xiàn)這個是由于g1在做gc時，都是先復(fù)制存活對象，再回收原region，當(dāng)沒有空閑空間復(fù)制存活對象時，就會出現(xiàn)to-space exhausted，而這種GC場景代價是非常大的。

同時，在這個gc發(fā)生之前，還發(fā)現(xiàn)了一些如下的日志。

這里可以看到，系統(tǒng)在分配約30M+的大對象，難道是有代碼頻繁分配大對象導(dǎo)致的gc問題。

jdk在分配大對象時，會調(diào)用G1CollectedHeap::humongous_obj_allocate方法，而使用async-profiler可以很容易知道哪里調(diào)用了這個方法，如下：

# 開啟收集
./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps

# 停止收集
./profiler.sh stop -f ./humongous.jfr jps

將humongous.jfr文件用jmc打開，如下：

根據(jù)調(diào)用棧我發(fā)現(xiàn)，這是我們的一個定時任務(wù)，它會定時調(diào)用一個接口獲取配置信息并緩存它，而這個接口返回的數(shù)據(jù)量達(dá)14M之多。

難道是這個接口導(dǎo)致的gc問題？但這個定時任務(wù)調(diào)用也不頻繁呀，5分鐘才調(diào)用一次，不至于讓gc忙不過來吧！另一個疑問是，這個定時任務(wù)在其它環(huán)境也會運行，而且其它環(huán)境的業(yè)務(wù)流量大得多，為什么其它環(huán)境沒有問題？

至此，我也不確定是這個定時任務(wù)導(dǎo)致的問題，還是系統(tǒng)自身特點導(dǎo)致偶爾的高gc耗時。

由于我們有固定的上線日，于是我打算先優(yōu)化產(chǎn)生大對象的代碼，然后在上線前的期間試著優(yōu)化一下jvm gc參數(shù)。

我們使用的是httpclient調(diào)用接口，調(diào)用接口時，代碼會先將接口返回數(shù)據(jù)讀取成String，然后再使用jackson把String轉(zhuǎn)成map對象，簡化如下：

rsp = httpClient.execute(request);
String result = IOUtils.toString(rsp.getEntity().getContent());
Map resultMap = JSONUtil.getMapper().readValue(result, Map.class);

要優(yōu)化它也很簡單，使用jackson的readValue有一個傳入InputStream的重載方法，用它來讀取json數(shù)據(jù)，而不是將其加載成一個大的String對象再讀，如下：

rsp = httpClient.execute(request);
InputStream is = rsp.getEntity().getContent();
Map resultMap = JSONUtil.getMapper().readValue(is, Map.class);

注：這里面map從邏輯上來說是一個大對象，但對jvm來說，它只是很多個小對象然后用指針連接起來而已，大對象一般由大數(shù)組造成，大String之所以是大對象，是因為它里面有一個很大的char[]數(shù)組。

優(yōu)化完代碼后，我開始研究優(yōu)化jvm gc參數(shù)了，我們使用的是jdk8，垃圾收集器是g1，為了理解g1的調(diào)優(yōu)參數(shù)，又簡單學(xué)習(xí)了下g1的關(guān)鍵概念。

g1是分region收集的，但region也分年輕代與老年代。

g1的gc分young gc與mixed gc，young gc用于收集年輕代region，mixed gc會收集年輕代與老年代region。

在mixed gc回收之前，需要先經(jīng)歷一個并發(fā)周期(Concurrent Cycles)，用來標(biāo)記各region的對象存活情況，讓mixed gc可以判斷出需要回收哪些region。

并發(fā)周期分為如下4個子階段：a. 初始標(biāo)記(initial marking)b. 并發(fā)標(biāo)記(concurrent marking)c. 重新標(biāo)記(remarking)d. 清理(clean up)需要注意的是，初始標(biāo)記(initial marking)這一步是借助young gc完成的。

在g1中，young gc幾乎沒有什么可調(diào)參數(shù)，而mixed gc有一些，常見如下：

出現(xiàn)to-space exhausted會不會是mixed gc太慢了呢？于是我調(diào)整了如下參數(shù)：

1. 讓并發(fā)標(biāo)記周期啟動更早，運行得更快，將-XX：InitiatingHeapOccupancyPercent從默認(rèn)值45%調(diào)整到35%，-XX:ConcGCThreads從1調(diào)整為3。
2. -XX:G1MixedGCLiveThresholdPercent與-XX:G1HeapWastePercent確定回收哪些region，有多少比例垃圾才執(zhí)行回收，我覺得它們的值本來就蠻激進(jìn)，就沒有調(diào)整。
3. -XX:G1MixedGCCountTarget與-XX:G1OldCSetRegionThresholdPercent控制mixed gc執(zhí)行多少次，每次回收多少region，我將-XX:G1OldCSetRegionThresholdPercent從10%調(diào)整到了15%，讓它一次多回收些old region。
4. 增加保留空間，避免復(fù)制存活對象失敗，將-XX:G1ReservePercent從10%調(diào)整到20%。
5. 盡量避免產(chǎn)生大對象，將-XX:G1HeapRegionSize增加到16m。

于是我按照上面調(diào)整了jvm參數(shù)，可是第二天我發(fā)現(xiàn)還是有GC長耗時，次數(shù)也沒有減少，看來問題根因和我調(diào)整的參數(shù)沒有關(guān)系。

問題根因

就這樣，到了上線日，于是我上線了前面優(yōu)化大對象的代碼，一天后，我發(fā)現(xiàn)偶爾的GC長耗時竟然沒有了！

問題就這樣解決了?。?！

然而我心里還是有一個大大的問號，其它環(huán)境同樣有這個定時任務(wù)，一樣的運行頻率，jvm配置也全是一樣的，為啥其它環(huán)境沒有問題呢？其它環(huán)境業(yè)務(wù)流量還大一些！

為此，我搜索了大量關(guān)于g1大對象的文章，我發(fā)現(xiàn)大對象的分配與回收過程有點特殊，如下：

1. 大于region size一半的對象是大對象，會直接分配在old region，且gc時大對象不會被復(fù)制或移動，而是直接回收。
2. 大對象回收發(fā)生在2個地方，一個是并發(fā)周期的clean up子階段，另一個是young gc(這個特性在jdk8u60才加入)。

我忽然想到，莫非是俄羅斯環(huán)境流量太低，觸發(fā)不了young gc，且并發(fā)周期又因為什么原因沒執(zhí)行，但定時任務(wù)又慢慢生成大對象將old region占滿，導(dǎo)致了to-space exhausted？

于是，我打算寫段代碼試驗一下，慢慢的只生成大對象，看g1會不會回收，如下：

這個一個命令行交互程序，使用如下jvm參數(shù)啟動它：

# 1600m的堆，16m的region size
# rlwrap作用是使得這個命令行程序更好用
rlwrap java -server -Xms1600m -Xmx1600m -Xss1m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=1g -Xloggc:/home/work/logs/applogs/gc-%t.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/work/logs/applogs/ -XX:+PrintClassHistogram -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintAdaptiveSizePolicy -XX:+UseG1GC -XX:G1LogLevel=finest -XX:G1HeapReginotallow=16m -XX:MaxGCPauseMillis=200 -jar command-cli.jar

使用了1600M的堆，16M的region size，所以總共有100個region，jdk版本是1.8.0_222。通過在這個交互程序中輸入gc 9437184 20 0，可以生成20個9M的大對象。

當(dāng)我輸入3次gc 9437184 20 0后，如下：我從gc日志中發(fā)現(xiàn)了一次由initial marking觸發(fā)的young gc，說明g1啟動了并發(fā)周期，之所以發(fā)生young gc，是因為initial marking是借助ygc執(zhí)行的。

緊接著，我發(fā)現(xiàn)了并發(fā)標(biāo)記、重新標(biāo)記與清理階段的日志。

然后我在jstat中發(fā)現(xiàn)老年代使用率降低了，因為young gc會回收大對象，所以老年代使用率降低也是正常的。

當(dāng)我又執(zhí)行了2次gc 9437184 20 0后，使得堆占用率再次大于45%，我發(fā)現(xiàn)gc日志中出現(xiàn)如下內(nèi)容：

看字面意思是，由于mixed gc正在執(zhí)行，沒有再次啟動并發(fā)周期。

可是，我在這種狀態(tài)下等了好久，也沒有看到mixed gc的日志出來，不是說mixed gc正在執(zhí)行嚒，它一定是有什么問題！

于是，我又執(zhí)行了好幾次gc 9437184 20 0，我在gc日志中發(fā)現(xiàn)了to-space exhausted！

1. 從上面do not start mixed GCs, reason: candidate old regions not available的日志中看到，mixed gc日志之所以長時間沒出來，是因為沒有可回收的region導(dǎo)致mixed gc沒有執(zhí)行，因為我們只創(chuàng)建了大對象，但mixed gc不回收大對象分區(qū)，所以確實是沒有可回收的region的。
2. 從Humongous Reclaimed: 98可以發(fā)現(xiàn)，這次young gc，回收了98個大對象分區(qū)，而我們總共只有100個分區(qū)，說明在inital marking之后創(chuàng)建的大對象，確實一直都沒有回收。

注：添加-XX:G1LogLevel=finest參數(shù)，才能輸出Humongous Reclaimed這一項。

但是，大對象分區(qū)占了98個，堆占用率肯定超過了45%，為何一直沒有再次啟動并發(fā)周期呢？

感覺這可能是jdk的bug，于是我分別下了最新的jdk8u與jdk11u驗證，發(fā)現(xiàn)問題在最新的jdk8u中依然存在，而jdk11u中則不存在，這應(yīng)該就是JDK的Bug！于是我通過二分搜索法多次編譯了不同版本的JDK，最終確定問題fix在jdk9_b93與jdk9_b94之間。

并在jdk的bug庫中，搜索到了相同描述的bug反饋，如下：

https://bugs.openjdk.org/browse/JDK-8140689

Bug改動代碼如下：

大致瞄了下代碼，可能理解得不完全正確，改動邏輯如下：

1. G1再次啟動并發(fā)周期之前，至少需要執(zhí)行過一次mixed gc或young gc，類似于Concurrent Cycles -> mixed gc|young gc -> Concurrent Cycles -> mixed gc|young gc。
2. 我們的場景是，在并發(fā)周期結(jié)束之后，由于沒有需要回收的分區(qū)，導(dǎo)致mixed gc實際沒有執(zhí)行，可是我們只分配了大對象，且大對象又只分配在old region，所以young gc也不可能被觸發(fā)，而由于上面的條件，Concurrent Cycles也不會被觸發(fā)，因此最終大對象將堆占滿觸發(fā)了to-space exhausted。
3. 修復(fù)邏輯是，當(dāng)并發(fā)周期結(jié)束后，沒有需要回收的分區(qū)時，should_continue_with_reclaim=false，進(jìn)而使得允許不執(zhí)行純young gc而直接啟動并發(fā)周期，類似于Concurrent Cycles -> Concurrent Cycles。

所以在使用JDK8時，像那種系統(tǒng)流量很小，新生代較大，又有定時任務(wù)不斷產(chǎn)生大對象的場景，堆幾乎必然會被慢慢占滿，要解決這個問題，可參考如下處理：

1. 優(yōu)化代碼，避免分配大對象。
2. 代碼無法優(yōu)化時，可考慮升級jdk11。
3. 無法升級jdk11時，可考慮減小-XX:G1MaxNewSizePercent讓新生代小一點，讓young gc能執(zhí)行得更頻繁些，同時老年代更大，能緩沖更多大對象分配。

考慮到我們負(fù)責(zé)的其它系統(tǒng)中，時不時就有一波大響應(yīng)體的請求，也沒法快速修改代碼，于是我統(tǒng)一將-XX:G1MaxNewSizePercent減小到30%，經(jīng)過觀察，修改后GC頻率有所增加，但暫停時間有所下降，這是符合期望的。

總結(jié)

當(dāng)我在jdk的bug庫中搜索問題時，發(fā)現(xiàn)不少和G1大對象相關(guān)的優(yōu)化，早期JDK(如JDK8)的G1實現(xiàn)可能在大對象回收上不太完善，所以寫代碼時要注意盡量少創(chuàng)建大對象，以回避這些隱性問題。

注：這之后又遇到了Update RS (ms)耗時高，竟也和大對象有關(guān)，添加-XX:-ReduceInitialCardMarks后解決，看來大對象是萬惡之源啊??