線上FGC調優案例三則

前言

閒魚服務端應用廣泛使用 Java 技術棧，基於JVM提供的託管式堆記憶體管理，開發者無需過多關心物件建立/回收時的記憶體分配/釋放動作，垃圾回收器（Garbage Collector）會在需要的時候自動清理堆內不再使用的物件，保證有可用空間用於新物件分配。
開發者在享受到自動記憶體管理的便利時，也不可避免的需要承擔垃圾回收器在進行死亡物件清理時的一些開銷，例如機器資源利用率上升，應用執行緒被短暫暫停等。根據JVM使用的垃圾回收演算法的不同以及回收的堆區域的不同，GC過程中使用者執行緒的暫停時間、完成一次GC的耗時、也有所不同。
其中，全堆記憶體清理（Full GC，下稱FGC）會掃描整個堆空間，清理掉所有死亡物件，而FGC是Stop the world（下文簡稱STW）的，也就是意味著會暫停全部的使用者執行緒直到GC結束。一趟FGC的停頓時長視堆空間大小和存活物件數量多少而定，通常從幾秒到幾十秒不等。在這期間，應用無法對外提供任何服務，表現為介面超時，成功率下降，上游依賴執行緒池打滿等，十分影響使用者體驗，甚至可能出現訪問壓力轉移到其他健康機器上，使得健康機器物件分配壓力增大，最終產生FGC而導致叢集雪崩。
對於前臺業務應用而言，正常承接業務流量的過程中產生的物件大部分都為朝生夕滅的物件，理論絕大部分物件上應該能通過新生代GC（YGC）被清理掉；而大部分GC演算法，都是在老年代佔用空間超過一定閾值時，才會觸發FGC。因此，一旦出現了FGC，通常意味著這個應用的物件分配或垃圾回收相關的JVM引數存在問題，是業務執行時的重大隱患，需要儘快排查並根治。
本文通過三則前臺應用FGC調優案例，分別介紹了由於JVM引數、中介軟體配置、業務程式碼層面引起的FGC的現象、分析過程及對應解法。希望能起到拋磚引玉的作用，以及給有同樣疑惑的讀者朋友們帶來一些啟發。

商品域核心應用釋出及執行時FGC

現象

閒魚商品域某核心應用，在正常承接業務流量時，叢集不時有少量FGC出現，引起介面RT毛刺及成功率略微下跌。在應用釋出過程中，叢集FGC次數明顯上升，介面抖動明顯，且大部分FGC出現在未在釋出批次的機器上。

此應用承接了對閒魚商品增刪改查操作的絕大部分流量。叢集執行時的FGC不僅會影響使用者體驗，成為以後業務發展過程中的重大隱患，而且釋出時的抖動會使得程式碼萬一出問題時沒辦法快速回退到上一個版本，是安全生產的重大風險，需要儘快解決。

分析

圖中不難得出大量有用的資訊：

1. 應用採用 ParNew + CMS組合。

2. 老年代到達1.7G左右佔用時，觸發CMS Old Gen GC。【1.7G可能是一個固定的Old Gen回收閾值】

3. 老年代佔用會隨著時間的推移緩慢升高，逐漸觸頂。【Survivor空間可能不夠用】

4. Old Gen GC 一次回收大約200MB，水位回落到 1.5G，單次回收收益不明顯。【老年代存在不少固定佔用的大物件】

從監控上看，這是一種非常明顯的因為擔保分配，使得一些最終會死亡的物件進入到老年代，老年代觸到CMS回收閾值產生CMS Old Gen GC的表象。但是在沒有充分的證據之前，並不能盲目的下結論，還需要繼續小心謹慎地求證上述假設，從而根據深層次的原因制定能根治FGC現象的解決方案。

針對假設1和2，檢視應用JVM引數配置：

可以看到，應用確實是使用CMS作為垃圾回收器，堆大小被配置為4G，Young區2G，Old區2G，CMSInitiatingOccupancyFraction引數被配置為80%，這意味著老年代佔用超過80%時觸發CMS Old Gen回收，2G*0.8 = 1.6G，差不多就是監控中體現的1.7G左右開始回收，然後老年代佔用回落。

另外還可以順便得到：SurvivorRatio=10，單個Survivor區 2048 * /(10+1+1) = 174762K左右這一結論，能夠為接下來的分析提供幫助。

對於假設3，監控系統上以分鐘為粒度聚合的折線圖就不太能滿足需求了，需要通過GC日誌，對機器每次GC回收結束後，各個區域的堆空間佔用進行分析，看是否存在一次YGC結束後，Survivor區佔用較高的情況。一段非常有代表性的GC日誌如下圖所示：

注意到ParNew是STW的演算法，不存在回收過程中物件分配的可能。而一次ParNew回收前後的堆空間變化可以用下圖來表示：

計算GC日誌中各個區域的存活物件佔用空間變化：
第一次回收: Young區 40225K存活，全堆1697070K存活，Old區1697070-40225=1656845K
第二次回收: Young區174720K存活，全堆1859440K存活，Old區1859440-174720=1684720K
Old區佔用上漲約27875K
而先前通過JVM引數，可以知道單個Survivor區大小約為174762K，第二次回收極有可能出現了擔保分配。Survivor區可能在某些回收中，顯得不夠用。

對於假設4，可以隨機找一臺線上機器，將流量切走後執行帶FGC的Heap dump，目的是拿到FGC過後的堆物件集合。檢視支配樹，如下圖所示：

可以看到排前4的物件已經佔用了老年代約 687MB的空間，整體約1.3G的物件常駐老年代空間。且這4個物件對於業務而言都是十分重要的物件，初步來看並沒有太大的優化空間。

分析到這裡，該應用FGC的根因就呼之欲出了。

根因

偶現Survivor不夠用的擔保分配(可能還有晉升) -> Old Gen佔用上漲 -> Old Gen 距離回收閾值僅有約200M的餘量 -> 頻繁 CMS Old Gen GC。

在應用釋出過程中，又因為正在啟動的應用，RPC、HTTP服務等沒有上線，或者是處於小流量預熱階段，整個叢集的流量就會傾斜到不在釋出流程中的機器，使得每臺機器需要承受的QPS升高，物件分配壓力增大，YGC次數增多，通過擔保分配晉升老年代的速率加快，導致老年代更快的觸頂，出現頻繁 FGC。

解法

雖然該應用的FGC成因並不難分析，但是為其制定一個能根治FGC的解法卻還是需要一些考量。

商品業務經過長時間的發展，該應用程式碼量非常大，業務邏輯錯綜複雜，且依賴了大量中介軟體、二方服務，很難去搞清楚這些業務物件的存活週期。要想解決這個應用的FGC現象，最好的辦法就是： 在不觸發FGC的前提下清理掉擔保到Old Gen的Young區存活物件。

該應用之前使用CMS回收器，但是通過後續分析發現，很難在CMS上達成上述目標。主要是因為存在以下幾點困難：

1. Survivor 存在不夠用現象。然而業務複雜，很難給出一個一定夠用的數字。盲目調大，擠佔了Young區的空間，導致YGC頻繁，可能存在 吞吐下降，RT升高 的風險。

2. Old Gen 常駐大物件多？考慮大物件治理。依賴的服務未必有治理方案、升級迴歸存在成本。

3. Old Gen固定閾值產生CMS Old Gen GC？
   調高閾值？有擔保分配失敗，回退到全堆STW FGC的風險。
   調大Old Gen？全堆大小不變的話擠佔Young區，風險同1。
   增大全堆大小？應用容器記憶體吃緊，有容器OOM程序被殺的風險，以及這麼做只是減少了Old Gen FGC的次數，沒法根治。 且存在Old區變大，CMS Old Gen GC耗時變長的風險。

最終決定更換垃圾回收器為G1GC，因為G1GC預設晉升代數15代，可以使得更少的物件晉升到老年代，且支援Mixed GC增量式回收老年代垃圾。因此通過擔保分配、晉升到Old區的垃圾可以通過Mixed GC清理。Mixed GC發生在YGC中，而G1的YGC又是能併發回收的，與ParNew相比具有更好的使用者體驗。

在G1GC預設的引數基礎上，使用 G1NewSizePercent 引數固定Eden下限30%，設定 InitiatingHeapOccupancyPercent 為60%，保證Eden區不會過於小影響吞吐量，留10%的餘量給Mixed GC時的併發分配動作；設定 MaxGCPauseMillis 為 120ms，期望稍微犧牲停頓時間換取更大吞吐量，以及Region大小4MB：期望GC能更精細的分配及標記Region，減少空間浪費。

成效

最終該應用釋出抖動消失，FGC消失，GC耗時相比優化前（CMS）總體下降近一半。業務高峰期物件分配壓力極大的時候，仍能控制在一分鐘GC總耗時不超過500ms的水平下清理老年區所有死亡物件。FGC現象被徹底根治。

首頁應用釋出FGC

現象

閒魚首頁應用，在釋出過程中每次都會存在一小批機器，在應用啟動後陷入FGC，必須手動重啟才能恢復；每次陷入FGC的機器IP均不重複，通過置換容器也無法解決問題。與上文提及的商品域應用不同的是，首頁應用在正常執行時不會出現FGC，正常機器的JVM堆監控及GC日誌顯示記憶體分配壓力不算太大，且該應用已經在使用G1GC。

分析

檢視發生FGC機器的JVM監控：

可以看到，從釋出開始之後，有問題的機器老年代空間持續上漲，隨後出現大量的FGC。從圖中的GC耗時來看，一分鐘有44.4s在FGC，7.9s在YGC。總計有52.3s處於GC狀態。應用基本上沒法響應外界請求。

從監控上看，也不難得知這是比較典型的堆記憶體洩漏。一般有兩種情況：無用物件不釋放，或者是物件存活週期由於某些原因而顯著變長，導致堆裡面存在大量存活物件，空間不夠用。對於這種情況，通常需要藉助Heap dump來觀察堆裡面究竟是什麼物件大量佔用空間。

從Heap dump結果中，發現堆裡面存在大量的Log4j RingBufferLogEvent，也就是說，堆裡有大量的Log4j非同步執行緒沒來得及消費的日誌請求。而且最大的訊息體竟然能到1.4M左右的大小。

通過對訊息體內部的字串分析，發現這是線上某個介面的出入參日誌。通過對線上請求的抓包分析，發現該介面返回的內容確實較多，平均在1M以上。而這些接口出入參，又確實需要通過打日誌的方式，上報到日誌平臺儲存起來，供排查問題使用。這種出入參記錄方式在閒魚被廣泛使用，通過review打日誌的程式碼，發現並沒有什麼明顯的問題。因此，問題基本上與應用的程式碼沒太大相關性。唯一值得注意的點是日誌體較大，考慮從日誌產生到落盤的整個流程入手分析，看整個過程是否存在效能瓶頸。

閒魚服務端應用為了提升打日誌效能，降低同步呼叫打日誌時出現IO Hang的風險，開啟了Log4j的非同步日誌列印功能。這也是Log4j官網比較推薦的一種效能優化方式。具體原理如下圖所示：

在正常情況下，應用程式碼呼叫日誌輸出方法後，傳入的日誌文字會被封裝成一個Event，投遞到Log4j內部的一個環形佇列中（由 disruptor 提供，這是一種無鎖跨執行緒通訊的庫，能夠提供比佇列更高的吞吐和更低的延遲）就立即返回。由Log4j的後臺執行緒不斷消費環形佇列中的Event，將日誌輸出到檔案上。

而 disruptor 中，環形佇列的容量是以slot為單位組織的。在正常情況下是一個應用全域性共享 262144 個slot。每個Event在RingBuffer中佔用一個slot，一個slot裡的 Event佔用空間大小則不做限制。

這就有可能出現以下的情況： 應用有可能打出很大的日誌，這就可能出現，Slot佔用並不多，但是每個Slot的Event都很大，記憶體消耗非常可觀。

另外，注意到應用使用的 Log4j 版本為 2.8.2，在官方的Jira上有一個issue: LOG4J2-2031 。此issue記載在某些情況下會出現日誌亂序以及日誌列印無響應的情況。原因是因為 2.8.2 中預設的 AsyncQueueFullPolicy 為 SYNCHRONOUS，此策略會在RingBuffer滿的時候繞過RingBuffer，直接向檔案輸出日誌內容，導致日誌亂序。

此外，還發現日誌輸出過程中，會把日誌message複製2遍，第一遍在 org.apache.logging.log4j.core.layout.PatternLayout#encode 裡toText呼叫，把日誌內容複製到自己維護的一個放在ThreadLocal的StringBuffer裡面。第二次是 encoder.encode(text, destination); 呼叫，會把StringBuffer的內容拷進RollingRandomAccessFileManager內部的ByteBuffer裡。所以，對於一個日誌寫入呼叫，峰值可能產生3倍記憶體佔用。如果日誌體很大的話，瞬時的堆佔用將非常可觀。可能出現來不及消費的日誌Event擠佔新生代空間，導致頻繁YGC，吞吐量下降及日誌Event物件晉升到老年代，進而出現FGC，由於FGC是STW的，會把Log4j後臺寫日誌的執行緒也暫停掉，進一步影響了後臺日誌消費執行緒的執行，導致情況進一步惡化。

對比2.8.2及2.14.1的原始碼，其中一處變化是修改了預設的非同步佇列滿策略：2.14.1判斷了當前日誌寫入執行緒是不是Log4j的回寫執行緒，如果不是，就讓當前執行緒等待RingBuffer消費出Slot。實踐證明，這樣的策略是更加合理的。

在日誌體較大的情況下，還有一個細節值得注意：有一個叫做 MessagePatternConverter 的 Converter。這個Converter是會搜尋整個日誌檔案，把 ${} 佔位符替換成真實值。具體實現是用了一個for迴圈的方法搜尋形如 ${ 的連續字元並加以處理。對於剛才那種上MB大小、且根本沒有 ${} 佔位符需要替換的的請求日誌，此特性只能是浪費計算資源，影響日誌消費速度。

public void format(final LogEvent event, final StringBuilder toAppendTo) {
    final Message msg = event.getMessage();
    if (msg instanceof StringBuilderFormattable) {


        final boolean doRender = textRenderer != null;
        final StringBuilder workingBuilder = doRender ? new StringBuilder(80) : toAppendTo;


        final int offset = workingBuilder.length();
        if (msg instanceof MultiFormatStringBuilderFormattable) {
            ((MultiFormatStringBuilderFormattable) msg).formatTo(formats, workingBuilder);
        } else {
            ((StringBuilderFormattable) msg).formatTo(workingBuilder);
        }


        // TODO can we optimize this?
      //  這裡，會全文搜尋 ${} 然後嘗試替換。如果不需要這個特性的場合都是可以關閉來提高效能的。
        if (config != null && !noLookups) {
            for (int i = offset; i < workingBuilder.length() - 1; i++) {
                if (workingBuilder.charAt(i) == '$' && workingBuilder.charAt(i + 1) == '{') {
                    final String value = workingBuilder.substring(offset, workingBuilder.length());
                    workingBuilder.setLength(offset);
                    workingBuilder.append(config.getStrSubstitutor().replace(event, value));
                }
            }
        }
        if (doRender) {
            textRenderer.render(workingBuilder, toAppendTo);
        }
        return;
    }
    if (msg != null) {
        String result;
        if (msg instanceof MultiformatMessage) {
            result = ((MultiformatMessage) msg).getFormattedMessage(formats);
        } else {
            result = msg.getFormattedMessage();
        }
        if (result != null) {
            toAppendTo.append(config != null && result.contains("${")
                    ? config.getStrSubstitutor().replace(event, result) : result);
        } else {
            toAppendTo.append("null");
        }
    }
}

根因

最終，我們認為導致此現象發生的原因是：冷 JVM 湧入大量大日誌列印請求 -> RingBuffer 大量佔用堆記憶體 + 日誌消費跟不上速度 -> 觸發YGC，甚至是STW FGC -> STW FGC暫停Log4j消費寫盤執行緒 -> 惡性迴圈，應用雪崩。

在問題排查過程中 ，還發現首頁應用使用的新版 AliJDK 在使用新版協程支援來處理執行緒間切換以及阻塞、喚醒呼叫時，存在極小概率出現排程器死迴圈，部分/全部執行緒失去響應，JVM僵死的情況。不排除協程排程器死迴圈可能影響Log4j日誌消費執行緒的情況。該場景極難復現，出現時Thread dump工具、JVM Agent等診斷工具均無法連線上JVM，看不到現場，排查難度高。
此外，全協程模型帶來的效能提升感知不強。因此，為了保險起見，處理此問題時，順便也關閉了新版協程，使得JVM回退到傳統的執行緒模型執行程式碼。

解法

對於該應用的FGC問題，採取4步走策略，逐個擊破：

1. RingBuffer大量佔用堆記憶體: 通過限制RingBuffer Slot數為一個合理值，保證應用中最大的LogEvent填滿RingBuffer時也不至於把堆撐爆。本應用設定的是2048。

一般情況下，該值不需要調整。因為通常情況下極少有應用會產生超大日誌體。如確實需要調整此引數，需要結合應用的日誌使用場景，分情況評估。

2. JVM過冷：延長新啟動機器小流量預熱時長。

3. Log4j 佇列滿時記憶體佔用過大：升級Log4j到2.14.1。使用新版佇列滿策略，同步等待佇列消費出slot。

4. Log消費過程存在無意義的計算：對於不需要佔位符替換的場景關閉佔位符替換特性，提高消費速度。

成效

應用上述策略後，釋出引數調整的修復分支。效果立竿見影，此分支釋出過程中無任何FGC發生。回訪應用負責人，此後所有的釋出均不再出現上文提及的FGC。

玩家業務應用執行時FGC

現象

某玩家業務應用，使用G1GC垃圾回收器，平時叢集正常承接業務流量，沒有FGC，物件分配壓力並不大。但是有一天叢集突然出現FGC，且隨著時間的推移FGC的頻率越來越高。機器重啟無法解決問題。

分析

檢視發生FGC機器的JVM監控，可惜監控並沒能給到太多有用的資訊：

從監控上看，堆使用率、YGC次數等都比較正常，機器執行過程中老年代基本上保持在相對穩定的水位，偶爾出現FGC時，也能迅速清理掉堆中死亡物件，使得佔用迅速回落到正常水位。因此基本可以排除記憶體洩漏、擔保分配、晉升等原因而出現的緩慢上升的老年代佔用。

從介面QPS、RT、Load等指標看，這些指標也非常平穩，可以排除有瞬時大流量衝擊機器導致爆發式業務壓力產生的FGC。多次FGC之間間隔並不規律；排查過定時任務排程平臺，也可以排除由於某些記憶體壓力較大的定時任務產生的FGC。

分析到這裡，沒有更好的辦法，把目光轉向FGC發生時的gc日誌、應用日誌，期望從日誌中得到有價值的資訊。

檢視gc日誌，發現在若干次正常的YGC後，存在一次to-space exhausted： 這是一次因為Eden區空間不夠而產生的YGC，而在這次YGC中Survivor區也不夠用。一般情況下G1GC因為會根據新生代物件存活率自適應調整Survivor區大小，基本上極少出現to-space exhausted。隨後日誌顯示Old區佔用上漲了數百MB。顯然，這預示著業務中有超大物件分配。

一旦知道有”超大物件”分配，方向就變得明朗了起來。G1認為佔用了超過Region大小一半的連續堆空間的物件是大物件。 且在大物件分配時，會給出大物件分配的呼叫棧。

該應用中配置的Region大小為32M，一半則為16M。

根因

通過排查上述呼叫棧的程式碼，發現是一句日誌列印的程式碼引發的血案。具體現場如下程式碼段所示：

// type definition


@Data
public class MapWrapper {
  // ...
    public Map<Key, Value> manyEntryMap;
  // ...
}
// biz code


MapWrapper instance = xxx;
log.info("print some log with plus concation! obj: " + instance);
// Correct way to print a log with object should be: 
// log.info("print some log with plus concation! obj: {}", instance);

一個類例項裡面封裝著一個有非常多的Entry的Map，這個類又因為有@Data註解，lombok會為其隱式實現toString方法。而在列印日誌過程中，使用 + 操作符連線字串和物件，會預設呼叫物件的toString方法，將物件轉化成字串形式。

該物件在沒轉換成字串的時候，雖然裡面的Map有非常多的Entry，但是都是分散在堆的各處的，不是連續的記憶體。體現為MapWrapper的支配堆空間可能很大，但是本體佔用十分小。

一旦呼叫toString方法，將物件轉換成字串形式時，就會把Map裡面每個entry都轉化成字串形式儲存在一個字串裡；而字串本體需要一段連續的記憶體來儲存char資訊，因此需要一段連續的堆空間來儲存這個字串。如果Map的Entry很多，那麼最終出來的字串就會很大，當超過了一半Region大小時，G1會認為這是一個大物件，直接分配到老年代。

更要命的是，底層在使用StringBuilder來append字串，當StringBuilder需要擴容時，會建立一個新的 char[] 陣列，並把原來的內容複製到新的char[]數組裡面。如果原來的 char[] 陣列已經是分配到老年代的大物件了，那新的char[]陣列也會被分配到老年代，最終一次toString可能產生好幾個駐留在老年代的大物件，儘管它們已經死亡。

反映到gc日誌上，即為老年代激增數百MB。

可能有讀者好奇，理論上一個日誌物件這麼大，應該能在磁碟利用率，磁碟寫入IO量等指標上有所反映。而該應用設定的線上環境日誌等級為WARN，這個產生了大物件分配的日誌列印等級為INFO。所以這個大物件不會打到磁碟上。因此，一條根本不會被列印到磁碟上的日誌，就因為一個小小的 + ，就多出了大量的計算工作、記憶體分配，甚至導致了線上FGC的發生。

解法

看上去複雜的問題，解法有時候反而非常簡單：可以通過修改程式碼，使用"{}"佔位符來拼接物件；也可以直接優化掉這句日誌列印。

成效

負責此業務的同學優化掉了上述日誌、排查了大Map產生的業務場景並做了相關優化。修復上線後，FGC消失。