升級到Spring 5.3.x之後，GC次數急劇增加，我TM人傻了

image

image

最近我們項目升級到了 Spring Boot 2.4.6 + Spring Cloud 2020.0.x，通過我的另一系列即可看出：Spring Cloud 升級之路。但是升級後，我們發現 YoungGC 明顯增高，分配對象速率明顯增高，但是晉陞的對象並沒有增多，證明都是新創建的對象並且沒過多久就可以被回收。我們來看其中一個進程的監控，這時候的 http 請求速率大概在 100 左右：

image

這就很奇怪了，請求速率並沒有那麼大，但是通過監控可以看出每秒鐘分配了將近兩個 G 的記憶體。在升級之前，這個分配速率大概在 100~200 MB 左右，在同等請求速率下。那麼這多出來的記憶體究竟是哪裡消耗的呢？

image

我們需要看一下記憶體中各種對象的統計數據，即使用 jmap 命令。同時不能只查看存活對象的統計，因為從監控中看出來並不是老年代對象過多，因為晉陞的對象並沒有增多，相反的，我們如果我們能排除現在還存活的對象就更好了。同時，由於 GC 相當頻繁，1s 左右就會有一次。所以基本不能期望一次就能抓到我們想要的 jmap。同時 jmap 會導致所有執行緒進入 safepoint 從而 STW，對線上有一定影響，所以不能太頻繁 jmap。所以，我們採取如下策略：

  1. 擴容一個實例，之後將一個實例，通過註冊中心以及限流器將某個實例的流量切走一半；
  2. 針對這個實例，連續執行 jmap -histo（統計所有對象） 以及 jmap -histo:live（僅統計存活對象）；
  3. 重複第二步 5 次，每次間隔 100ms，300ms，500ms，700ms；
  4. 去掉限流這個實例的限流，將新擴容的實例關閉。

通過這幾次的 jmap 對比，我們發現 jmap 統計中排在前面的對象類型有一個 spring 框架的：

 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:       7993252      601860528  [B ([email protected])
   2:        360025      296261160  [C ([email protected])
   3:      10338806      246557984  [Ljava.lang.Object; ([email protected])
   4:       6314471      151547304  java.lang.String ([email protected])
   5:         48170      135607088  [J ([email protected])
   6:        314420      126487344  [I ([email protected])
   7:       4591109      110100264  [Ljava.lang.Class; ([email protected])
   8:        245542       55001408  org.springframework.core.ResolvableType
   9:        205234       29042280  [Ljava.util.HashMap$Node; ([email protected])
  10:        386252       24720128  [org.springframework.core.ResolvableType;
  11:        699929       22397728  java.sql.Timestamp ([email protected])
  12:         89150       21281256  [Ljava.beans.PropertyDescriptor; ([email protected])
  13:        519029       16608928  java.util.HashMap$Node ([email protected])
  14:        598728       14369472  java.util.ArrayList ([email protected])

這個對象是怎麼創建出來的呢？如何定位一個已經不再存活的頻繁創建對象，並且這個對象類型是框架內部的？

首先，MAT（Eclipse Memory Analyzer）+ jmap dump 這種整個堆分析，並不太適用，原因是：

  1. 對象已經不再存活，MAT 更適合對於記憶體泄漏的分析，我們這裡是創建出來很多預期外的對象，佔用了大量記憶體，這些對象很快就不再存活。
  2. MAT 對於不再存活的對象，無法準確分析出創建者，主要因為 dump 的時候不確定是否能抓到我們想要的資訊，或者有很多資訊雜訊。

雖然這個問題不能這麼定位，我還是將我採集的 jmap dump 結果放在這裡用 MAT 分析的結果展示出來給大家看下：

那麼接下來怎麼分析呢？這就又用到了我們的老朋友，JFR + JMC。老讀者知道，我經常使用 JFR 定位線上問題，這裡怎麼使用呢？並沒有直接的 JFR 事件統計經常創建哪些對象，但是呢，有間接的事件，可以間接體現是誰創建了這麼多對象。我一般這麼定位：

  1. 通過執行緒分配對象統計事件查看是哪個執行緒分配對象過多（Thread Allocation Statistics）。
  2. 通過熱點程式碼分析哪些熱點程式碼可能會產生這些對象（Method Profiling Sample）。像這種大量創建的對象，抓取 Runnable 程式碼很大概率被抓取到，並且在事件中佔比高。

首先查看 Thread Allocation Statistics 事件，發現基本上所有 servlet 執行緒（就是處理 Http 請求的執行緒，我們用的 Undertow，所以執行緒名稱是 XNIO 開頭的），分配的對象都很多，這樣並不能定位問題：

image

然後我們來看熱點程式碼統計，點擊 Method Profiling Sample 事件，查看堆棧追蹤統計，看哪些佔比比較高。

image

發現佔比靠前的，貌似都和這個 ResolvableType 有關，進一步定位，雙擊第一個方法查看調用堆棧統計：

image

我們發現，調用它的是 BeanUtils.copyProperties。查看其它ResolvableType 有關的調用，都和BeanUtils.copyProperties有關。這個方法是我們項目中經常使用的方法，用於同類型或者不同類型之間的屬性複製。這個方法為何會創建這麼多 ResolvableType 呢？

image

通過查看源碼，我們發現從 Spring 5.3.x 開始，BeanUtils 開始通過創建 ResolvableType 這個統一類資訊封裝，進行屬性複製：


/**
 * 
 * <p>As of Spring Framework 5.3, this method honors generic type information
 */
private static void copyProperties(Object source, Object target, @Nullable Class<?> editable,
		@Nullable String... ignoreProperties) throws BeansException {
}

裡面的源碼，每次都針對源對象和目標對象的類型的每個屬性方法創建了新的 ResolvableType，並且沒有做快取。這導致一次複製，會創建出來大量的 ResolvableType.我們來做個試驗：

public class Test {
    public static void main(String[] args)  {
        TestBean testBean1 = new TestBean("1", "2", "3", "4", "5", "6", "7", "8", "1", "2", "3", "4", "5", "6", "7", "8");
        TestBean testBean2 = new TestBean();
        for (int i = 0; i > -1; i++) {
            BeanUtils.copyProperties(testBean1, testBean2);
            System.out.println(i);
        }
    }
}

分別使用 spring-beans 5.2.16.RELEASE 和 spring-beans 5.3.9 這兩個依賴去執行這個程式碼，JVM 參數使用 -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC -Xmx512m.這些參數的意思是，使用 EpsilonGC，也就是在堆記憶體滿的時候，不執行 GC，直接拋出 OutofMemory 異常並程式結束，並且最大堆記憶體是 512m。這樣，程式其實就是看：在記憶體耗盡之前，不同版本的 BeanUtils.copyProperties 分別能執行多少次。

試驗結果是：spring-beans 5.2.16.RELEASE 是 444489 次，spring-beans 5.3.9 是 27456 次。這是相當大的差距啊。

於是，針對這個問題，我向 spring-framework github 提了個 Issue.

然後，對於項目中經常使用 BeanUtils.copyProperties 的地方，替換成使用 BeanCopier，並且封裝了一個簡單類：

public class BeanUtils {
    private static final Cache<String, BeanCopier> CACHE = Caffeine.newBuilder().build();

    public static void copyProperties(Object source, Object target) {
        Class<?> sourceClass = source.getClass();
        Class<?> targetClass = target.getClass();
        BeanCopier beanCopier = CACHE.get(sourceClass.getName() + " to " + targetClass.getName(), k -> {
            return BeanCopier.create(sourceClass, targetClass, false);
        });
        beanCopier.copy(source, target, null);
    }
}

但是需要注意的是，BeanCopier替換BeanUtils.copyProperties最直接的一個問題就是：對於屬性不同但是名字不同的無法複製。例如一個是 int 另一個是  Integer 也不行。同時還有深拷貝的一些區別，需要我們做好單元測試。

修改好後，問題解決。

微信搜索「我的編程喵」關注公眾號，每日一刷，輕鬆提升技術，斬獲各種offer：

image

Tags:

VirMach 便宜 VPS