一次压测引出的线上Full GC排查

最新推荐文章于 2023-07-02 18:57:35 发布

DP成长之路

最新推荐文章于 2023-07-02 18:57:35 发布

阅读量297

点赞数

分类专栏： JVM与高并发

原文链接：https://mp.weixin.qq.com/s/N7YKNGHL3g6oEXKUcTDlZg

版权

JVM与高并发专栏收录该内容

22 篇文章 2 订阅

订阅专栏

这个 Full GC 问题是去年双 12 压测的时候触发的，中间排查的过程和踩的坑给大家借鉴一下。

线上问题

双 12 之前压测的时候起了很小的量，直接触发了 Full GC，吓尿了，因为马上双 12 大促预热就要开始了，这搞不好妥妥的 3.25 啦。

赶紧拉群，把相关同学拉在一起排查问题。

第一时间查看GC日志：

2020-11-29T21:11:11.887+0800: [Full GC (Metadata GC Threshold) 2020-11-29T21:11:11.88+880: [CMS: 2401176K->675327K(3584000k), 2.9603365 secs] 3246233K-675327K (5519368K), (Metaspace: 243832K->231459K (1275984K)), 2.965466 secs) [Times: user=2.94 sys=8.84, real-2.96 secs)

可以看到原因是超过了 Metadata GC 的阈值，触发了 Full GC。Metaspace 从 243M 回收到 231M，基本没怎么回收掉。所以稍微再来点量，很容易再次触发 Metaspace 的回收。

知识储备

GC 问题排查需要很多储备知识，最主要是 JVM 相关的，之前文章已经讲过一些了，这里主要讲 Metaspace 是什么？后面讲怎么做的 GC 问题的排查。

这里有两个知识点：

Metaspace（元空间）是什么？在 JVM 中扮演什么角色，也就是存放什么的？
Full GC 跟 Metaspace 大小设置有什么关系？

Metaspace 叫做元空间。从JDK 8开始，永久代（PermGen）的概念被废弃掉了，取而代之的是一个称为 Metaspace 的存储空间。

Metaspace 用来存放 class 文件在 JVM 里的运行时数据结构，以及存储 Klass 相关的其他的内容，比如 Method，ConstantPool 等。

Metaspace 使用的是本地内存，而不是堆内存。也就是说在默认情况下 Metaspace 的大小只与本地内存大小有关。但是很容易有个误区：Metaspace 可以随便用，不管使用多少，只要不超本地内存就不会触发 GC，这是错误的。

Metaspace 的设置方式是：-XX: MetaspaceSize=**M。这个 JVM 参数的作用是让Metaspace 达到 MetaspaceSize 时触发 Full GC。

如果不设置 Metaspace, 默认值很小，也就 20M 左右（不同系统会有一点差别）。如果程序 Load Class 比较多，很容易触发 Full GC。这里要明白的是 Class 信息和加载 Class 的 ClassLoader 都存放在 Metaspace。我们知道一个类是由这个类的类加载器加上全限定名（由包名&类名组成）确定唯一性的。

所以大家可以检查一下自己应用 JVM Metaspace 的设置大小。如果没有做设置，可以通过 -XX:+PrintFlagsInitial 查看一下默认值。

问题排查

刚开始看到 Full GC 频繁，查看日志是由于Metaspace 空间不够造成的，第一反应是调整 Metaspace 大小，把 MetaspaceSize 从 256M 提高到了 512M。但是发现 Metaspace 引发的 Full GC 还是没有消除。

立即 dump 了两台机器的日志。第一次分析GC 日志文件，没发现异常，这里有个注意的地方，大家 dump 文件时机很重要。有时候 dump 的 GC 日志没问题是因为刚好 Full GC 完成之后 dump 的，内存回收的干干净净。有些内存缓慢增加的问题一定要在 Full GC 前 dump。

期间，我们还发现缓存相关的对象占用内存较高。但是经过分析，缓存对象生命周期本身就比较长，所以常驻在堆上，没有问题。继续看。

排查发现 Metaspace 内存占用是随着双 12 新接口压测流量的增长而增长，所以可以确定是新接口代码引入。

分析 GC dump 日志发现可疑点：同一个 ClassCloader 加载了接近 3000 个，如下图所示。前面我们说过，ClassCloader 信息保存在 Metaspace 区域。

破案了，fastjson 使用不当引入了 ASM Serializer 的坑。

故障定位与修复

FastJson 之所以快，原因就是使用 asm 字节码增强替代了反射。所以肯定是代码中应用了 fastjson 的 ASM 处理数据时造成的频繁加载同一个类。基本问题清楚了，那就是撸代码了，很快就定位了问题代码。

因为保密原因，不方便放原始代码，安琪拉撸了个类似逻辑的代码：

for(Item item -> arrays) {  SerializeConfig serializeConfig = new SerializeConfig();   serializeConfig.put(Custom.class, new CustomSerializer());   jsonString = JSON.toJSONString(item, serializeConfig);}

这段代码是自定义了一个序列化实现类 CustomSerializer，在进行序列化时进行了一个类似 AOP 的切面处理，对所有 Custom 类型的字段进行统一自定义序列化（使用CustomSerializer）。

实现原理是，对需要序列化的 Class 使用 asm 动态生成了代理类，在这里就是 Item 类。使用 SerializeConfig 配置动态生成字节码代理类：com.alibaba.fastjson.serializer.ASMSerializer_1_Item。但是每次 new SerializeConfig 对象（内存地址不一样），FastJson 会当作每次代理的是不一样的目标。导致每次会使用一个新的类加载器 ASMClassLoader，所以 Metaspace 很快就满了，触发了频繁Full GC。

如果希望深入研究可以看下 FastJson 源码：com.alibaba.fastjson.serializer.SerializeConfig#createASMSerializer。

问题修复

SerializeConfig.getGlobalInstance().put(Character.class, new CharacterSerializer());

SerializeConfig 改成单例的后，每次序列化不用重复加载。

类似问题排查与调优

如果 dump 日志发现很多 classloader 名称前缀相同，排查是否有这种动态代理技术的使用，可能在不断生成代理对象；
发现内存缓慢增长 GC 回收不掉，dump GC 日志，查看是否有类被重复加载；
Metaspace 调优，比如我们现在生产环境 Metaspace 基本会设置 256M 或者 512M，可以根据应用的类型和机器内存配置来决定。取决于两个因素：是否会加载比较多的类；机器内存允许, 可以适当调大 Metaspace。

以上就是双 12 压测 GC 问题完整的排查方法论、详细过程和解决方案。