升级到Spring 5.3.x之后，GC次数急剧增加，我TM人傻了

Posted 2021-09-04 干货满满张哈希

最近我们项目升级到了 Spring Boot 2.4.6 + Spring Cloud 2020.0.x，通过我的另一系列即可看出：Spring Cloud 升级之路。但是升级后，我们发现 YoungGC 明显增高，分配对象速率明显增高，但是晋升的对象并没有增多，证明都是新创建的对象并且没过多久就可以被回收。我们来看其中一个进程的监控，这时候的 http 请求速率大概在 100 左右：

这就很奇怪了，请求速率并没有那么大，但是通过监控可以看出每秒钟分配了将近两个 G 的内存。在升级之前，这个分配速率大概在 100~200 MB 左右，在同等请求速率下。那么这多出来的内存究竟是哪里消耗的呢？

我们需要看一下内存中各种对象的统计数据，即使用 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 开头的），分配的对象都很多，这样并不能定位问题：

然后我们来看热点代码统计，点击 Method Profiling Sample 事件，查看堆栈追踪统计，看哪些占比比较高。

发现占比靠前的，貌似都和这个 ResolvableType 有关，进一步定位，双击第一个方法查看调用堆栈统计：

我们发现，调用它的是 BeanUtils.copyProperties。查看其它ResolvableType 有关的调用，都和BeanUtils.copyProperties有关。这个方法是我们项目中经常使用的方法，用于同类型或者不同类型之间的属性复制。这个方法为何会创建这么多 ResolvableType 呢？

通过查看源码，我们发现从 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：