GC耗時高，原因竟是服務流量小？

原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，轉載請保留出處。

簡介

最近，我們系統配置了GC耗時的監控，但配置上之後，系統會偶爾出現GC耗時大於1s的報警，排查花了一些力氣，故在這裡分享下。

發現問題

我們系統分多個環境部署，出現GC長耗時的是俄羅斯環境，其它環境沒有這個問題，這裡比較奇怪的是，俄羅斯環境是流量最低的一個環境，而且大多數GC長耗時發生在深夜。

發現報警後，我立馬查看了GC日誌，如下： 

日誌中出現了to-space exhausted，經過一番瞭解，出現這個是由於g1在做gc時，都是先複製存活對象，再回收原region，當沒有空閑空間複製存活對象時，就會出現to-space exhausted，而這種GC場景代價是非常大的。

同時，在這個gc發生之前，還發現了一些如下的日誌。

這裡可以看到，系統在分配約30M+的大對象，難道是有代碼頻繁分配大對象導致的gc問題。

定位大對象產生位置

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

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

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

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

根據調用棧我發現，這是我們的一個定時任務，它會定時調用一個介面獲取配置信息並緩存它，而這個介面返回的數據量達14M之多。

難道是這個介面導致的gc問題？但這個定時任務調用也不頻繁呀，5分鐘才調用一次，不至於讓gc忙不過來吧！
另一個疑問是，這個定時任務在其它環境也會運行，而且其它環境的業務流量大得多，為什麼其它環境沒有問題？

至此，我也不確定是這個定時任務導致的問題，還是系統自身特點導致偶爾的高gc耗時。

由於我們有固定的上線日，於是我打算先優化產生大對象的代碼，然後在上線前的期間試著優化一下jvm gc參數。

優化產生大對象的代碼

我們使用的是httpclient調用介面，調用介面時，代碼會先將介面返回數據讀取成String，然後再使用jackson把String轉成map對象，簡化如下：

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

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

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

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

優化GC參數

優化完代碼後，我開始研究優化jvm gc參數了，我們使用的是jdk8，垃圾收集器是g1，為了理解g1的調優參數，又簡單學習了下g1的關鍵概念。

1. g1是分region收集的，但region也分年輕代與老年代。
2. g1的gc分young gc與mixed gc，young gc用於收集年輕代region，mixed gc會收集年輕代與老年代region。
3. 在mixed gc回收之前，需要先經歷一個併發周期(Concurrent Cycles)，用來標記各region的對象存活情況，讓mixed gc可以判斷出需要回收哪些region。
4. 併發周期分為如下4個子階段：
   a. 初始標記(initial marking)
   b. 併發標記(concurrent marking)
   c. 重新標記(remarking)
   d. 清理(clean up)
   需要註意的是，初始標記(initial marking)這一步是藉助young gc完成的。

在g1中，young gc幾乎沒有什麼可調參數，而mixed gc有一些，常見如下：

出現to-space exhausted會不會是mixed gc太慢了呢？於是我調整瞭如下參數：

1. 讓併發標記周期啟動更早，運行得更快，將-XX：InitiatingHeapOccupancyPercent從預設值45%調整到35%，-XX:ConcGCThreads從1調整為3。
2. -XX:G1MixedGCLiveThresholdPercent與-XX:G1HeapWastePercent確定回收哪些region，有多少比例垃圾才執行回收，我覺得它們的值本來就蠻激進，就沒有調整。
3. -XX:G1MixedGCCountTarget與-XX:G1OldCSetRegionThresholdPercent控制mixed gc執行多少次，每次回收多少region，我將-XX:G1OldCSetRegionThresholdPercent從10%調整到了15%，讓它一次多回收些old region。
4. 增加保留空間，避免複製存活對象失敗，將-XX:G1ReservePercent從10%調整到20%。
5. 儘量避免產生大對象，將-XX:G1HeapRegionSize增加到16m。

於是我按照上面調整了jvm參數，可是第二天我發現還是有GC長耗時，次數也沒有減少，看來問題根因和我調整的參數沒有關係。

問題根因

就這樣，到了上線日，於是我上線了前面優化大對象的代碼，一天後，我發現偶爾的GC長耗時竟然沒有了！

問題就這樣解決了！！！

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

為此，我搜索了大量關於g1大對象的文章，我發現大對象的分配與回收過程有點特殊，如下：

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

我忽然想到，莫非是俄羅斯環境流量太低，觸發不了young gc，且併發周期又因為什麼原因沒執行，但定時任務又慢慢生成大對象將old region占滿，導致了to-space exhausted？

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

這個一個命令行交互程式，使用如下jvm參數啟動它：

# 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:G1HeapRegionSize=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的大對象。

當我輸入3次gc 9437184 20 0後，如下：
我從gc日誌中發現了一次由initial marking觸發的young gc，說明g1啟動了併發周期，之所以發生young gc，是因為initial marking是藉助ygc執行的。

緊接著，我發現了併發標記、重新標記與清理階段的日誌。

然後我在jstat中發現老年代使用率降低了，因為young gc會回收大對象，所以老年代使用率降低也是正常的。

當我又執行了2次gc 9437184 20 0後，使得堆占用率再次大於45%，我發現gc日誌中出現如下內容：

看字面意思是，由於mixed gc正在執行，沒有再次啟動併發周期。

可是，我在這種狀態下等了好久，也沒有看到mixed gc的日誌出來，不是說mixed gc正在執行嚒，它一定是有什麼問題！

於是，我又執行了好幾次gc 9437184 20 0，我在gc日誌中發現了to-space exhausted！

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

註：添加-XX:G1LogLevel=finest參數，才能輸出Humongous Reclaimed這一項。

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

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

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

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

Bug改動代碼如下：

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

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

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

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

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

總結

當我在jdk的bug庫中搜索問題時，發現不少和G1大對象相關的優化，早期JDK(如JDK8)的G1實現可能在大對象回收上不太完善，所以寫代碼時要註意儘量少創建大對象，以迴避這些隱性問題。

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