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

扣釘日記發表於2023-01-07
GC

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

簡介

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

發現問題

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

發現報警後，我立馬檢視了GC日誌，如下： 
image_2023-01-05_20230105150159
日誌中出現了to-space exhausted，經過一番瞭解，出現這個是由於g1在做gc時，都是先複製存活物件，再回收原region，當沒有空閒空間複製存活物件時，就會出現to-space exhausted，而這種GC場景代價是非常大的。

同時，在這個gc發生之前，還發現了一些如下的日誌。
image_2023-01-02_20230102214444
這裡可以看到，系統在分配約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開啟，如下：
image_2023-01-02_20230102215823
根據呼叫棧我發現，這是我們的一個定時任務，它會定時呼叫一個介面獲取配置資訊並快取它，而這個介面返回的資料量達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有一些，常見如下：

引數 作用
-XX:InitiatingHeapOccupancyPercent 開始mixed gc併發週期的堆佔用閾值，當大於此比例，啟動併發週期，預設45%
-XX:ConcGCThreads 在併發標記時，使用多少個併發執行緒。
-XX:G1HeapRegionSize 每個region大小，當分配物件尺寸大於region一半時，才認為這是一個大物件。
-XX:G1MixedGCLiveThresholdPercent region存活比例，預設85%，當併發標記後發現region中存活物件比例小於這個值，mixed gc才會回收這個region，畢竟一個region如果都是存活的物件，那還有什麼回收的必要呢。
-XX:G1HeapWastePercent 允許浪費的堆比例，預設5%，當可回收的記憶體比例大於此值時，mixed gc才會去執行回收，畢竟沒什麼可回收的物件時，還有什麼回收的必要呢。
-XX:G1MixedGCCountTarget mixed gc執行的次數，一旦併發標記週期確認了回收哪些region後，mixed gc就進行回收，但mixed gc會分少量多次來回收這些region，預設8次。
-XX:G1OldCSetRegionThresholdPercent 每次mixed gc回收old region的比例，預設10%，如果G1MixedGCCountTarget是8的話，mixed gc整體能回收80%。
-XX:G1ReservePercent 堆保留空間比例，預設10%，這部分空間g1會保留下來，用來在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會不會回收，如下：
image_2023-01-02_20230102222318
這個一個命令列互動程式，使用如下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執行的。
image_2023-01-02_20230102223208

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

然後我在jstat中發現老年代使用率降低了，因為young gc會回收大物件，所以老年代使用率降低也是正常的。
image_2023-01-02_20230102222752

當我又執行了2次gc 9437184 20 0後，使得堆佔用率再次大於45%，我發現gc日誌中出現如下內容：
image_2023-01-02_20230102224057
看字面意思是，由於mixed gc正在執行，沒有再次啟動併發週期。

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

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

  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之間。
image_2023-01-07_20230107204406
並在jdk的bug庫中，搜尋到了相同描述的bug反饋，如下：
image_2023-01-07_20230107203043
https://bugs.openjdk.org/browse/JDK-8140689

Bug改動程式碼如下：
image_2023-01-07_20230107203133
大致瞄了下程式碼，可能理解得不完全正確，改動邏輯如下：

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

相關文章