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

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

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

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

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

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

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

# 開啟收集
./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)，這是我們的一個(gè)定時(shí)任務(wù)，它會(huì)定時(shí)調(diào)用一個(gè)接口獲取配置信息并緩存它，而這個(gè)接口返回的數(shù)據(jù)量達(dá)14M之多。

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

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

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

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

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

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

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

注：這里面map從邏輯上來說是一個(gè)大對(duì)象，但對(duì)jvm來說，它只是很多個(gè)小對(duì)象然后用指針連接起來而已，大對(duì)象一般由大數(shù)組造成，大String之所以是大對(duì)象，是因?yàn)樗锩嬗幸粋€(gè)很大的char[]數(shù)組。

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

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

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

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

并發(fā)周期分為如下4個(gè)子階段：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會(huì)不會(huì)是mixed gc太慢了呢？于是我調(diào)整了如下參數(shù)：

1. 讓并發(fā)標(biāo)記周期啟動(dòng)更早，運(yùn)行得更快，將-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ù)制存活對(duì)象失敗，將-XX:G1ReservePercent從10%調(diào)整到20%。
5. 盡量避免產(chǎn)生大對(duì)象，將-XX:G1HeapRegionSize增加到16m。

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

問題根因

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

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

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

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

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

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

于是，我打算寫段代碼試驗(yàn)一下，慢慢的只生成大對(duì)象，看g1會(huì)不會(huì)回收，如下：

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

# 1600m的堆，16m的region size
# rlwrap作用是使得這個(gè)命令行程序更好用
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個(gè)region，jdk版本是1.8.0_222。通過在這個(gè)交互程序中輸入gc 9437184 20 0，可以生成20個(gè)9M的大對(duì)象。

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

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

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

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

看字面意思是，由于mixed gc正在執(zhí)行，沒有再次啟動(dòng)并發(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日志之所以長(zhǎng)時(shí)間沒出來，是因?yàn)闆]有可回收的region導(dǎo)致mixed gc沒有執(zhí)行，因?yàn)槲覀冎粍?chuàng)建了大對(duì)象，但mixed gc不回收大對(duì)象分區(qū)，所以確實(shí)是沒有可回收的region的。
2. 從Humongous Reclaimed: 98可以發(fā)現(xiàn)，這次young gc，回收了98個(gè)大對(duì)象分區(qū)，而我們總共只有100個(gè)分區(qū)，說明在inital marking之后創(chuàng)建的大對(duì)象，確實(shí)一直都沒有回收。

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

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

感覺這可能是jdk的bug，于是我分別下了最新的jdk8u與jdk11u驗(yàn)證，發(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改動(dòng)代碼如下：

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

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

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

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

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

總結(jié)

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

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