引言
背景
服务新功能发版一周后下午，突然收到 CMS GC 告警，导致单台节点被拉出，随后集群内每个节点先后都发生了一次 CMS GC，拉出后的节点垃圾回收后接入流量恢复正常（事后排查发现被重启了）。
排查过程
GC 日志排查
GC 问题首先排查的应该是 GC 日志，日志能能够清晰的判定发生 GC 的那一刻是什么导致的 GC，通过分析 GC 日志，能够清晰的得出 GC 哪一部分在出问题，如下是 GC 日志示例：
0.514: [GC (Allocation Failure [PSYoungGen: 4445K->1386K(28672K] 168285K->165234K(200704K, 0.0036830 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.518: [Full GC (Ergonomics [PSYoungGen: 1386K->0K(28672K] [ParOldGen: 163848K->165101K(172032K] 165234K->165101K(200704K, [Metaspace: 3509K->3509K(1056768K], 0.0103061 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
0.528: [GC (Allocation Failure [PSYoungGen: 0K->0K(28672K] 165101K->165101K(200704K, 0.0019968 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.530: [Full GC (Allocation Failure [PSYoungGen: 0K->0K(28672K] [ParOldGen: 165101K->165082K(172032K] 165101K->165082K(200704K, [Metaspace: 3509K->3509K(1056768K], 0.0108352 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
如上 GC 日志能很明显发现导致 Full GC 的问题是：Full GC 之后，新生代内存没有变化，老年代内存使用从 165101K 降低到 165082K （几乎没有变化）。这个程序最后内存溢出了，因为没有可用的堆内存创建 70m 的大对象。
JVM 监控埋点排查
上述 GC 日志丢失问题基本无解，发生 GC 则立即重建，除非人为干预，否则很难拿到当时的 GC 日志，且很难预知下次发生 GC 问题时间（如果能上报 GC 日子就不会有这样的问题，事后发现有，但是我没找到。）。
事故现场”，通过监控，可以清楚的看到 JVM 内部在时间线上是如何分配内存及回收内存的。
主要关注的核心指标如下：
- GC（垃圾收集）瞬时和累计详情
- FullGC 次数
- YoungGC 次数
- FullGC 耗时
- YoungGC 耗时
- 堆内存详情
- 堆内存总和
- 堆内存老年代字节数
- 堆内存年轻代 Survivor 区字节数
- 堆内存年轻代 Eden 区字节数
- 已提交内存字节数
- 非堆内存提交字节数
- DirectBuffer 总大小（字节）
- 线程总数量
堆内存排查
首先查看堆内存，确认是否有内存溢出（指无法申请足够的内存导致），对内监控如下：
可以看到发生 Full GC 后，堆内存明显降低了很多，但是在未发生大量 Full GC 后也有内存回收到和全量 GC 同等位置，所以可以断定堆内存是可以正常回收的，不是导致大量 Full GC 的元凶。
非堆内存排查
Metaspace 是用来干嘛的？JDK8 的到来，JVM 不再有 PermGen（永久代），但类的元数据信息（metadata）还在，只不过不再是存储在连续的堆空间上，而是移动到叫做 “Metaspace” 的本地内存（Native memory）中。
- 程序运行时：当运行 Java 程序时，该程序所需的类和方法。
- 类被引用时：当程序首次引用某个类时，加载该类。
- 反射：当使用反射 API 访问某个类时，加载该类。
- 动态代理：当使用动态代理创建代理对象时，加载该对象所需的类。
由上得出结论，如果一个服务内没有大量的反射或者动态代理等类加载需求时，讲道理，程序启动后，类的加载数量应该是波动很小的（不排除一些异常堆栈反射时也会加载类导致增加），但是如上监控显示，GC 后，metaspace 的内存使用量一直缓步增长，即程序内不停地制造“类”。
查看当前 JVM 设置的非堆内存大小如下：
程序代码排查
由上面排查得出的结论：程序内在大量的创建类导致非堆内存被打爆。结合当前服务内存在大量使用 Groovy 动态脚本功能，大概率应该是创建脚本出了问题，脚本创建动态类代码如下：
public static GroovyObject buildGroovyObject(String script {
GroovyClassLoader classLoader = new GroovyClassLoader(;
try {
Class<?> groovyClass = classLoader.parseClass(script;
GroovyObject groovyObject = (GroovyObject groovyClass.newInstance(;
classLoader.clearCache(;
log.info("groovy buildScript success: {}", groovyObject;
return groovyObject;
} catch (Exception e {
throw new RuntimeException("buildScript error", e;
} finally {
try {
classLoader.close(;
} catch (IOException e {
log.error("close GroovyClassLoader error", e;
}
}
}
线上打开日志，确实证明了在不停的创建类。
public static GroovyObject buildScript(String scriptId, String script {
Validate.notEmpty(scriptId, "scriptId is empty";
Validate.notEmpty(scriptId, "script is empty";
// 尝试缓存获取
String currScriptMD5 = DigestUtils.md5DigestAsHex(script.getBytes(;
if (GROOVY_OBJECT_CACHE_MAP.containsKey(scriptId
&& currScriptMD5.equals(GROOVY_OBJECT_CACHE_MAP.get(scriptId.getScriptMD5( {
log.info("groovyObjectCache hit, scriptId: {}", scriptId;
return GROOVY_OBJECT_CACHE_MAP.get(scriptId.getGroovyObject(;
}
// 创建
try {
GroovyObject groovyObject = buildGroovyObject(script;
// 塞入缓存
GROOVY_OBJECT_CACHE_MAP.put(scriptId, GroovyCacheData.builder(
.scriptMD5(currScriptMD5
.groovyObject(groovyObject
.build(;
} catch (Exception e {
throw new RuntimeException(String.format("scriptId: %s buildGroovyObject error", scriptId, e;
}
return GROOVY_OBJECT_CACHE_MAP.get(scriptId.getGroovyObject(;
}
此处代码逻辑在之前的测试中都是反复验证过的，不会存在问题，即只有缓存 Key 出问题导致了类的重复加载。结合最近修改上线的逻辑，排查后发现，scriptId 存在重复的可能，导致不同脚本，相同 scriptId 不停重复加载（加载的频次 10 分钟更新一次，所以非堆使用缓慢上升）。
此处埋了一个小坑：加载的类使用 Map 存储的，即同一个 cacheKey 调用 Map.put( 方法，重复加载的类会被后面加载的类给替换掉，即之前加载的类已经不在被 Map 所“持有”，会被垃圾回收器回收掉，按理来说 Metaspace 不应该一直增长下去！？
类加载与 Groovy 类加载、Metaspace 何时会被回收。
总结
知其然知其所以然。
gceasy.io 在线 GC 日志分析工具，此处笔者参照了美团技术团队文章 Java 中 9 种常见的 CMS GC 问题分析与解决 收益匪浅，推荐大家阅读。
往期精彩
个人技术博客：https://jifuwei.github.io/ >