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

乾貨滿滿張雜湊發表於2021-08-06
SpringGC

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 (java.base@11.0.8)
   2:        360025      296261160  [C (java.base@11.0.8)
   3:      10338806      246557984  [Ljava.lang.Object; (java.base@11.0.8)
   4:       6314471      151547304  java.lang.String (java.base@11.0.8)
   5:         48170      135607088  [J (java.base@11.0.8)
   6:        314420      126487344  [I (java.base@11.0.8)
   7:       4591109      110100264  [Ljava.lang.Class; (java.base@11.0.8)
   8:        245542       55001408  org.springframework.core.ResolvableType
   9:        205234       29042280  [Ljava.util.HashMap$Node; (java.base@11.0.8)
  10:        386252       24720128  [org.springframework.core.ResolvableType;
  11:        699929       22397728  java.sql.Timestamp (java.sql@11.0.8)
  12:         89150       21281256  [Ljava.beans.PropertyDescriptor; (java.desktop@11.0.8)
  13:        519029       16608928  java.util.HashMap$Node (java.base@11.0.8)
  14:        598728       14369472  java.util.ArrayList (java.base@11.0.8)

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

首先，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

相關文章