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

布满荆棘的人生 2022-09-03 10:21 15阅读 0赞

![image][]

![image][image 1]

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

![image][image 2]

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

![image][image 3]

我们需要看一下**内存中各种对象的统计数据**，即使用 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][image 4]

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

![image][image 5]

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

![image][image 6]

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

![image][image 7]

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

[image]: /images/20220829/3b8fe4f6a428466db40e2ad050bb920a.png
[image 1]: /images/20220829/1e5157d22e63486ca113fce5ba9e1566.png
[Spring Cloud]: https://www.zhihu.com/column/c_1264858575866302464
[image 2]: /images/20220829/6ee72bf413f94371a2aea23cb6292018.png
[image 3]: /images/20220829/f392ff63b6fe46a3a64b86003d372cac.png
[image 4]: /images/20220829/0005474c997a4601b943225fd7b1b2a8.png
[image 5]: /images/20220829/0a7a577ab64c46f8a44edc9d07ceba72.png
[image 6]: /images/20220829/7aa50a1c32a4437ea95c04a306e1f312.png
[image 7]: /images/20220829/111f352efcfc4a16b076ae8ff1ad8ce6.png
[Issue]: https://github.com/spring-projects/spring-framework/issues/27246
[image 8]: /images/20220829/0240f4d284c14bdf89db891622e94d0a.png