記一次線上FGC問題排查-有解無憂

引言

本文記錄一次線上 GC 問題的排查程序與思路，希望對各位讀者有所幫助，程序中也走了一些彎路，現在有時間沉淀下來思考并總結出來分享給大家，希望對大家今后排查線上 GC 問題有幫助，

背景

服務新功能發版一周后下午，突然收到 CMS GC 告警，導致單臺節點被拉出，隨后集群內每個節點先后都發生了一次 CMS GC，拉出后的節點垃圾回收后接入流量恢復正常（事后排查發現被重啟了），

告警資訊如下（已脫敏）：

多個節點幾乎同時發生 GC 問題，且排查自然流量監控后發現并未有明顯增高，基本可以確定是有 GC 問題的，需要解決，

排查程序

GC 日志排查

GC 問題首先排查的應該是 GC 日志，日志能能夠清晰的判定發生 GC 的那一刻是什么導致的 GC，通過分析 GC 日志，能夠清晰的得出 GC 哪一部分在出問題，如下是 GC 日志示例：

0.514: [GC (Allocation Failure) [PSYoungGen: 4445K->1386K(28672K)] 168285K->165234K(200704K), 0.0036830 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.518: [Full GC (Ergonomics) [PSYoungGen: 1386K->0K(28672K)] [ParOldGen: 163848K->165101K(172032K)] 165234K->165101K(200704K), [Metaspace: 3509K->3509K(1056768K)], 0.0103061 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
0.528: [GC (Allocation Failure) [PSYoungGen: 0K->0K(28672K)] 165101K->165101K(200704K), 0.0019968 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.530: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(28672K)] [ParOldGen: 165101K->165082K(172032K)] 165101K->165082K(200704K), [Metaspace: 3509K->3509K(1056768K)], 0.0108352 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

如上 GC 日志能很明顯發現導致 Full GC 的問題是：Full GC 之后，新生代記憶體沒有變化，老年代記憶體使用從 165101K 降低到 165082K （幾乎沒有變化），這個程式最后記憶體溢位了，因為沒有可用的堆記憶體創建 70m 的大物件，

但是，生產環境總是有奇奇怪怪的問題，由于服務部署在 K8s 容器，且運維有對服務心跳檢測，當程式觸發 Full GC 時，整個系統 Stop World，連續多次心跳檢測失敗，則判定為當前節點可能出故障（硬體、網路、BUG 等等問題），則直接拉出當前節點，并立即重建，此時之前列印的 GC 日志都是在當前容器卷內，一旦重建，所有日志全部丟失，也就無法通過 GC 日志排查問題了，

JVM 監控埋點排查

上述 GC 日志丟失問題基本無解，發生 GC 則立即重建，除非人為干預，否則很難拿到當時的 GC 日志，且很難預知下次發生 GC 問題時間（如果能上報 GC 日子就不會有這樣的問題，事后發現有，但是我沒找到，，），

此時，另一種辦法就是通過 JVM 埋點監控來排查問題，企業應用都會配備完備的 JVM 監控看板，就是為了能清晰明了的看到“事故現場”，通過監控，可以清楚的看到 JVM 內部在時間線上是如何分配記憶體及回收記憶體的，

JVM 監控用于監控重要的 JVM 指標，包括堆記憶體、非堆記憶體、直接緩沖區、記憶體映射緩沖區、GC 累計資訊、執行緒數等，

主要關注的核心指標如下：

GC（垃圾收集）瞬時和累計詳情
- FullGC 次數
- YoungGC 次數
- FullGC 耗時
- YoungGC 耗時
堆記憶體詳情
- 堆記憶體總和
- 堆記憶體老年代位元組數
- 堆記憶體年輕代 Survivor 區位元組數
- 堆記憶體年輕代 Eden 區位元組數
- 已提交記憶體位元組數
元空間元空間位元組數
非堆記憶體
- 非堆記憶體提交位元組數
- 非堆記憶體初始位元組數
- 非堆記憶體最大位元組數
直接緩沖區
- DirectBuffer 總大小（位元組）
- DirectBuffer 使用大小（位元組）
JVM 執行緒數
- 執行緒總數量
- 死鎖執行緒數量
- 新建執行緒數量
- 阻塞執行緒數量
- 可運行執行緒數量
- 終結執行緒數量
- 限時等待執行緒數量
- 等待中執行緒數量

發生 GC 問題，重點關注的就是這幾個指標，大致就能圈定 GC 問題了，

堆記憶體排查

首先查看堆記憶體，確認是否有記憶體溢位（指無法申請足夠的記憶體導致），對內監控如下：

可以看到發生 Full GC 后，堆記憶體明顯降低了很多，但是在未發生大量 Full GC 后也有記憶體回收到和全量 GC 同等位置，所以可以斷定堆記憶體是可以正常回收的，不是導致大量 Full GC 的元兇，

非堆記憶體排查

非堆記憶體指 Metaspace 區域，監控埋點如下：

可以看到發生告警后，非堆記憶體瞬間回收很多（因為服務器被健康檢查判定失效后重建，相當于重新啟動，JVM 重新初始化），此處如果有 GC 排查經驗的人一定能立即篤定，metaspace 是有問題的，

Metaspace 是用來干嘛的？JDK8 的到來，JVM 不再有 PermGen（永久代），但類的元資料資訊（metadata）還在，只不過不再是存盤在連續的堆空間上，而是移動到叫做 “Metaspace” 的本地記憶體（Native memory）中，

那么何時會加載類資訊呢？

程式運行時：當運行 Java 程式時，該程式所需的類和方法，
類被參考時：當程式首次參考某個類時，加載該類，
反射：當使用反射 API 訪問某個類時，加載該類，
動態代理：當使用動態代理創建代理物件時，加載該物件所需的類，

由上得出結論，如果一個服務內沒有大量的反射或者動態代理等類加載需求時，講道理，程式啟動后，類的加載數量應該是波動很小的（不排除一些例外堆疊反射時也會加載類導致增加），但是如上監控顯示，GC 后，metaspace 的記憶體使用量一直緩步增長，即程式內不停地制造“類”，

查看 JVM 加載類監控如下：

由上監控，確實是加載了大量的類，數量趨勢和非堆使用量趨勢吻合，

查看當前 JVM 設定的非堆記憶體大小如下：

MetaspaceSize & MaxMetaspaceSize = 1024 M，由上面非堆記憶體使用監控得出，使用量已接近 1000 M，無法在分配足夠的記憶體來加載類，最終導致發生 Full GC 問題，

程式代碼排查

由上面排查得出的結論：程式內在大量的創建類導致非堆記憶體被打爆，結合當前服務記憶體在大量使用 Groovy 動態腳本功能，大概率應該是創建腳本出了問題，腳本創建動態類代碼如下：

public static GroovyObject buildGroovyObject(String script) {
    GroovyClassLoader classLoader = new GroovyClassLoader();
    try {
        Class<?> groovyClass = classLoader.parseClass(script);
        GroovyObject groovyObject = (GroovyObject) groovyClass.newInstance();
        classLoader.clearCache();

        log.info("groovy buildScript success: {}", groovyObject);
        return groovyObject;
    } catch (Exception e) {
        throw new RuntimeException("buildScript error", e);
    } finally {
        try {
            classLoader.close();
        } catch (IOException e) {
            log.error("close GroovyClassLoader error", e);
        }
    }
}

線上打開日志，確實證明了在不停的創建類，

腳本創建類導致堆記憶體被打爆，之間也是踩過坑的，針對同一個腳本（MD5 值相同），則會直接拿快取，不會重復創建類，快取 check 邏輯如下：

public static GroovyObject buildScript(String scriptId, String script) {
    Validate.notEmpty(scriptId, "scriptId is empty");
    Validate.notEmpty(scriptId, "script is empty");

    // 嘗試快取獲取
    String currScriptMD5 = DigestUtils.md5DigestAsHex(script.getBytes());
    if (GROOVY_OBJECT_CACHE_MAP.containsKey(scriptId)
            && currScriptMD5.equals(GROOVY_OBJECT_CACHE_MAP.get(scriptId).getScriptMD5())) {
        log.info("groovyObjectCache hit, scriptId: {}", scriptId);
        return GROOVY_OBJECT_CACHE_MAP.get(scriptId).getGroovyObject();
    }

    // 創建
    try {
        GroovyObject groovyObject = buildGroovyObject(script);

        // 塞入快取
        GROOVY_OBJECT_CACHE_MAP.put(scriptId, GroovyCacheData.builder()
                .scriptMD5(currScriptMD5)
                .groovyObject(groovyObject)
                .build());
    } catch (Exception e) {
        throw new RuntimeException(String.format("scriptId: %s buildGroovyObject error", scriptId), e);
    }

    return GROOVY_OBJECT_CACHE_MAP.get(scriptId).getGroovyObject();
}

此處代碼邏輯在之前的測驗中都是反復驗證過的，不會存在問題，即只有快取 Key 出問題導致了類的重復加載，結合最近修改上線的邏輯，排查后發現，scriptId 存在重復的可能，導致不同腳本，相同 scriptId 不停重復加載（加載的頻次 10 分鐘更新一次，所以非堆使用緩慢上升），

此處埋了一個小坑：加載的類使用 Map 存盤的，即同一個 cacheKey 呼叫 Map.put() 方法，重復加載的類會被后面加載的類給替換掉，即之前加載的類已經不在被 Map 所“持有”，會被垃圾回收器回收掉，按理來說 Metaspace 不應該一直增長下去！？

提示：類加載與 Groovy 類加載、Metaspace 何時會被回收，

由于篇幅原因，本文就不在此處細究原因了，感興趣的朋友自行 Google 或者關注一下我，后續我再專門開一章詳解下原因，

總結

知其然知其所以然，

想要系統性地掌握 GC 問題處理方法，還是得了解 GC 的基礎：基礎概念、記憶體劃分、分配物件、收集物件、收集器等，掌握常用的分析 GC 問題的工具，如 gceasy.io 在線 GC 日志分析工具，此處筆者參照了美團技術團隊文章 Java 中 9 種常見的 CMS GC 問題分析與解決收益匪淺，推薦大家閱讀，

往期精彩

性能調優——小小的 log 大大的坑
性能優化必備——火焰圖
Flink 在風控場景實時特征落地實戰

歡迎關注公眾號：咕咕雞技術專欄
個人技術博客：https://jifuwei.github.io/ >

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/542672.html

標籤：Java

上一篇：垃圾收集器必問系列—ZGC

下一篇：SpringBoot專案動態定時任務之 ScheduledTaskRegistrar（解決方案一）