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/brow...

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後解決，看來大物件是萬惡之源啊?