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

標籤：其他

上一篇：多載的奧義之函式多載

下一篇：【Python】pip的鏡像安裝例外解決方案