記一次JVM Full GC (Metadata GC Threshold)調優經歷

記一次JVM Full GC (Metadata GC Threshold)調優經歷

一、背景：

線上服務器內存使用超過90%，分析上面部署的各個服務的GC日志，發現有一個服務的JVM內存分配過大，使用率較低，有調優的空間，可以在不遷移服務或者不升級服務器配置的情況下，降低服務器內存占用。

JVM推薦配置原則：

1. 應用程序運行時，計算老年代存活對象的占用空間大小X。程序整個堆大小（Xmx和Xms）設置為X的3 ~ 4倍；永久代PermSize和MaxPermSize設置為X的1.2 ~ 1.5倍。年輕代Xmn的設置為X的1 ~ 1.5倍。老年代內存大小設置為X的2 ~ 3倍。
2. JDK官方建議年輕代占整個堆大小空間的3/8左右。
3. 完成一次Full GC后，應該釋放出70%的堆空間（30%的空間仍然占用）。

觀察線上

發現2G的堆內存，Full GC之后的活躍對象才占用60M。按照推薦設置JVM內存只需要給幾百M就好了。所以決定改成1G，既能夠降低服務器內存占用，也預留了足夠的業務增長空間。

在這個過程中，發現如下幾個問題：

1. GC日志沒有時間顯示，看起來很不方便
2. GC日志沒有滾動，時間久了，日志文件較大
3. GC日志中存在大量Full GC (Metadata GC Threshold)

顯然第三個問題最為嚴重。我們知道，元數據區主要是用來存儲類的元數據的。一般來講，類加載完成之后，大小應該是比較穩定的，不會有太大變動。所以可以判斷，這么頻繁的Full GC (Metadata GC Threshold)，肯定是哪里出問題了。

但是我們一步一步來解決問題，而且GC日志不夠詳細也影響我們定位問題。

二、優化GC日志打印

首先復習一下JVM的GC日志打印的啟動參數。詳見官方介紹

• -verbose:gc

同-XX:+PrintGC

• -XX:+PrintGC

最簡單的 GC 參數 會打印 GC 前后堆空間使用情況以及 GC 花費的時間

• -XX:+PrintGCDetails

打印GC的詳細信息，會打印 youngGC FullGC前后堆【新生代，老年代，永久區】的使用情況以及 GC 時用戶態 CPU 耗時及系統 CPU 耗時及 GC 實際經歷的時間

• -XX:+PrintGCTimeStamps

打印CG發生的時間戳，從應用啟動開始累計的時間戳

• -XX:+PrintGCDateStamps

打印GC發生的時刻，所處日期時間信息

• -Xloggc:gc.log

指定GC log的位置，以文件輸出

• -XX:+PrintHeapAtGC

每一次GC前和GC后，都打印堆信息。

所以通過增加-XX:+PrintGCDateStamps解決我的第一個問題。

其次，JVM滾動記錄GC日志參數如下：

• -XX:UseGCLogFileRotation

打開或關閉GC日志滾動記錄功能，要求必須設置 -Xloggc參數。

• -XX:NumberOfGCLogFiles

設置滾動日志文件的個數，必須大於等於1。日志文件命名策略是， .0, .1, ..., .n-1，其中n是該參數的值。

• -XX:GCLogFileSize

設置滾動日志文件的大小，必須大於8k。當前寫日志文件大小超過該參數值時，日志將寫入下一個文件。

不過需要注意的是，如果設置滾動，最好保留足夠多的滾動日志，以免異常時的GC日志被沖掉。

三、Full GC排查

3.1 現象

最后，我們來解決Full GC (Metadata GC Threshold)的問題。

以下是系統重新啟動之后，從GC日志中grep出的Full GC日志。

可以觀察到如下幾個現象：

• 前幾次Full GC, 元數據區的空間並沒有釋放。
• 元數據區Full GC前的占用空間會逐漸增大至趨於一個比較穩定的值
• Full GC過於頻繁，幾乎沒30秒一次Full GC，這太誇張。

3.2 相關知識及分析

抱着這些疑問，我們學習一下metadata的啟動參數配置項：

• -XX:MetaspaceSize

這個參數是初始化的Metaspace大小，該值越大觸發Metaspace GC的時機就越晚。隨着GC的到來，虛擬機會根據實際情況調控Metaspace的大小，可能增加上線也可能降低。在默認情況下，這個值大小根據不同的平台在12M到20M浮動。使用java -XX:+PrintFlagsInitial命令查看本機的初始化參數，-XX:Metaspacesize為21810376B（大約20.8M）。

• -XX:MaxMetaspaceSize
  這個參數用於限制Metaspace增長的上限，防止因為某些情況導致Metaspace無限的使用本地內存，影響到其他程序。在本機上該參數的默認值為4294967295B（大約4096MB）。

• -XX:MinMetaspaceFreeRatio
  當進行過Metaspace GC之后，會計算當前Metaspace的空閑空間比，如果空閑比小於這個參數，那么虛擬機將增長Metaspace的大小。在本機該參數的默認值為40，也就是40%。設置該參數可以控制Metaspace的增長的速度，太小的值會導致Metaspace增長的緩慢，Metaspace的使用逐漸趨於飽和，可能會影響之后類的加載。而太大的值會導致Metaspace增長的過快，浪費內存。

• -XX:MaxMetasaceFreeRatio
  當進行過Metaspace GC之后， 會計算當前Metaspace的空閑空間比，如果空閑比大於這個參數，那么虛擬機會釋放Metaspace的部分空間。在本機該參數的默認值為70，也就是70%。

• -XX:MaxMetaspaceExpansion
  Metaspace增長時的最大幅度。在本機上該參數的默認值為5452592B（大約為5MB）。

• -XX:MinMetaspaceExpansion
  Metaspace增長時的最小幅度。在本機上該參數的默認值為340784B（大約330KB為）。

那么我們可以得到結論：

• 前幾次Full GC，是因為默認的-XX:MetaspaceSize 設置的太小而導致的。我們可以根據自己的應用情況適當調大。
• 后面逐漸增大並動態穩定的原因是-XX:MinMetaspaceFreeRatio和-XX:MaxMetasaceFreeRatio這兩個參數在起作用。空閑比 = GC釋放內存/GC前的大小，GC釋放得太多，就縮小MetaSpaceSize，釋放得太少，就擴大MetaSpaceSize。

同時，復習一下元數據區GC的相關知識：

Metaspace中的類需要滿足什么條件才能夠被當成垃圾被卸載回收？

條件還是比較嚴苛的，需同時滿足如下三個條件的類才會被卸載：

1. 該類所有的實例都已經被回收；
2. 加載該類的ClassLoader已經被回收；
3. 該類對應的java.lang.Class對象沒有任何地方被引用。

從GC日志我們可以看到，Metaspace已使用內存在Full GC后明顯變小（219105K -> 92087K），說明Metaspace經過Full GC后，確實卸載了很多類。

從這點來看，我們有理由懷疑系統可能在頻繁地生成大量”一次性“的類，導致Metaspace所占用空間不斷增長，增長到GC閾值后觸發Full GC。

那么這些被回收的類是什么呢？為了弄清楚這點，我增加了如下兩個JVM啟動參數來觀察類的加載、卸載信息：

-XX:TraceClassLoading -XX:TraceClassUnloading

加了這兩個參數后，系統跑了一段時間，從GC日志中發現大量如下的日志：

將Aviator與Full GC做一個關聯搜索，果然遇到這個問題的，不止我一個。

同時也在作者的github上找到相關的issue.

3.3 源碼解析

查看代碼我們可以看到Aviator提供了兩個調用接口：

public static Object execute(String expression, Map<String, Object> env, boolean cached) {
	return getInstance().execute(expression, env, cached);
}
public static Object execute(String expression, Map<String, Object> env) {
	return execute(expression, env, false);
}

深入源碼：

public Expression compile(final String expression, final boolean cached) {
        if (expression != null && expression.trim().length() != 0) {
            if (cached) {
                FutureTask<Expression> task = (FutureTask)this.cacheExpressions.get(expression);
                if (task != null) {
                    return this.getCompiledExpression(expression, task);
                } else {
                    task = new FutureTask(new Callable<Expression>() {
                        public Expression call() throws Exception {
                            return AviatorEvaluatorInstance.this.innerCompile(expression, cached);
                        }
                    });
                    FutureTask<Expression> existedTask = (FutureTask)this.cacheExpressions.putIfAbsent(expression, task);
                    if (existedTask == null) {
                        existedTask = task;
                        task.run();
                    }

                    return this.getCompiledExpression(expression, existedTask);
                }
            } else {
                return this.innerCompile(expression, cached);
            }
        } else {
            throw new CompileExpressionErrorException("Blank expression");
        }
    }

可以發現核心方法是innerCompile方法。繼續深入找到cached參數最底層的使用：

public AviatorClassLoader getAviatorClassLoader(boolean cached) {
        return cached ? this.aviatorClassLoader : new AviatorClassLoader(Thread.currentThread().getContextClassLoader());
    }

綜上，我們發現

• cached參數為true時，會優先從緩存中獲取編譯好的表達式對象。同時使用編譯表達式使用的類加載器也是同一個。
• 而cached為false時，每次執行表達式都會去編譯表達式，且每次編譯使用的是一個全新的類加載器。這是導致元數據區加載太多"一次性"類的元凶。

四、問題解決

最終，在調用參數中，將cached設置為true，成功解決Full GC (Metadata GC Threshold)問題。

成功解決該問題，內存使用率由原先的90%多下降到80%左右這樣一個比較健康的水平，能夠給業務增長留有空間。

觀察GC日志，也沒有Full GC (Metadata GC Threshold)的日志了。

通過這次調優過程，學習鞏固了一些 JVM GC相關的啟動參數，並對Metadata元數據區的內存管理有了更加詳細的認識。