乐趣区

关于gc:记一次线上FGC问题排查

jiezi

引言

本文记录一次线上 GC 问题的排查过程与思路，心愿对各位读者有所帮忙。过程中也走了一些弯路，当初有工夫积淀下来思考并总结进去分享给大家，心愿对大家今后排查线上 GC 问题有帮忙。

背景

服务新性能发版一周后下午，忽然收到 CMS GC 告警，导致单台节点被拉出，随后集群内每个节点先后都产生了一次 CMS GC，拉出后的节点垃圾回收后接入流量恢复正常（预先排查发现被重启了）。

告警信息如下（已脱敏）：

多个节点简直同时产生 GC 问题，且排查天然流量监控后发现并未有显著增高，根本能够确定是有 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 的大对象。

然而，生产环境总是有奇奇怪怪的问题，因为服务部署在 K8s 容器，且运维有对服务心跳检测，当程序触发 Full GC 时，整个零碎 Stop World，间断屡次心跳检测失败，则断定为以后节点可能出故障（硬件、网络、BUG 等等问题），则间接拉出以后节点，并立刻重建，此时之前打印的 GC 日志都是在以后容器卷内，一旦重建，所有日志全副失落，也就无奈通过 GC 日志排查问题了。

JVM 监控埋点排查

上述 GC 日志失落问题根本无解，产生 GC 则立刻重建，除非人为干涉，否则很难拿到过后的 GC 日志，且很难预知下次产生 GC 问题工夫（如果能上报 GC 日子就不会有这样的问题，预先发现有，然而我没找到。。）。

此时，另一种方法就是通过 JVM 埋点监控来排查问题。企业应用都会装备齐备的 JVM 监控看板，就是为了能清晰明了的看到“事故现场”，通过监控，能够分明的看到 JVM 外部在工夫线上是如何分配内存及回收内存的。

JVM 监控用于监控重要的 JVM 指标，包含堆内存、非堆内存、间接缓冲区、内存映射缓冲区、GC 累计信息、线程数等。

次要关注的外围指标如下：

  • GC（垃圾收集）刹时和累计详情

    • FullGC 次数
    • YoungGC 次数
    • FullGC 耗时
    • YoungGC 耗时

  • 堆内存详情

    • 堆内存总和
    • 堆内存老年代字节数
    • 堆内存年老代 Survivor 区字节数
    • 堆内存年老代 Eden 区字节数
    • 已提交内存字节数
  • 元空间元空间字节数

  • 非堆内存

    • 非堆内存提交字节数
    • 非堆内存初始字节数
    • 非堆内存最大字节数

  • 间接缓冲区

    • DirectBuffer 总大小（字节）
    • DirectBuffer 应用大小（字节）

  • JVM 线程数

    • 线程总数量
    • 死锁线程数量
    • 新建线程数量
    • 阻塞线程数量
    • 可运行线程数量
    • 终结线程数量
    • 限时期待线程数量
    • 期待中线程数量

产生 GC 问题，重点关注的就是这几个指标，大抵就能圈定 GC 问题了。

堆内存排查

首先查看堆内存，确认是否有 内存溢出（指无奈申请足够的内存导致），对内监控如下：

能够看到产生 Full GC 后，堆内存明显降低了很多，然而在未产生大量 Full GC 后也有内存回收到和全量 GC 等同地位，所以能够判定堆内存是能够失常回收的，不是导致大量 Full GC 的首恶。

非堆内存排查

非堆内存指 Metaspace 区域，监控埋点如下：

能够看到产生告警后，非堆内存霎时回收很多（因为服务器被健康检查断定生效后重建，相当于重新启动，JVM 从新初始化），此处如果有 GC 排查教训的人肯定能立刻笃定，metaspace 是有问题的。

Metaspace 是用来干嘛的？JDK8 的到来，JVM 不再有 PermGen（永恒代），但类的元数据信息（metadata）还在，只不过不再是存储在间断的堆空间上，而是挪动到叫做“Metaspace”的本地内存（Native memory）中。

那么何时会加载类信息呢？

  • 程序运行时：当运行 Java 程序时，该程序所需的类和办法。
  • 类被援用时：当程序首次援用某个类时，加载该类。
  • 反射：当应用反射 API 拜访某个类时，加载该类。
  • 动静代理：当应用动静代理创立代理对象时，加载该对象所需的类。

由上得出结论，如果一个服务内没有大量的反射或者动静代理等类加载需要时，讲道理，程序启动后，类的加载数量应该是稳定很小的（不排除一些异样堆栈反射时也会加载类导致减少），然而如上监控显示，GC 后，metaspace 的内存使用量始终缓步增长，即程序内不停地制作“类”。

查看 JVM 加载类监控如下：

由上监控，的确是加载了大量的类，数量趋势和非堆使用量趋势吻合。

查看以后 JVM 设置的非堆内存大小如下：

MetaspaceSize & MaxMetaspaceSize = 1024 M，由下面非堆内存应用监控得出，使用量已靠近 1000 M，无奈在调配足够的内存来加载类，最终导致产生 Full GC 问题。

程序代码排查

由下面排查得出的论断：程序外在大量的创立类导致非堆内存被打爆。联合以后服务内存在大量应用 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);
        }
    }
}

线上关上日志，的确证实了在不停的创立类。

脚本创立类导致堆内存被打爆，之间也是踩过坑的，针对同一个脚本（MD5 值雷同），则会间接拿缓存，不会反复创立类，缓存 check 逻辑如下：

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 何时会被回收。

因为篇幅起因，本文就不在此处细究起因了，感兴趣的敌人自行 Google 或者关注一下我，后续我再专门开一章详解下起因。

总结

知其然知其所以然。

想要系统性地把握 GC 问题解决办法，还是得理解 GC 的根底：根底概念、内存划分、调配对象、收集对象、收集器等。把握罕用的剖析 GC 问题的工具，如 gceasy.io 在线 GC 日志剖析工具，此处笔者参照了美团技术团队文章 Java 中 9 种常见的 CMS GC 问题剖析与解决 收益匪浅，举荐大家浏览。

往期精彩

  • 性能调优——小小的 log 大大的坑
  • 性能优化必备——火焰图
  • Flink 在风控场景实时特色落地实战

欢送关注公众号：咕咕鸡技术专栏
集体技术博客：https://jifuwei.github.io/ >

退出移动版