掘金 后端 ( ) • 2024-04-24 09:35

theme: orange

本文为稀土掘金技术社区首发签约文章,30天内禁止转载,30天后未获授权禁止转载,侵权必究!

本篇文章不涉及底层的 JDK bug 之类的问题,更主要的是JVM 内存分析思路和 NMT 相关的一些用法。

♟️先来一个场景

我们生产中出现了一个情况,当我们的核心应用连续运行超过半个月的时候,就会莫名的宕掉。

由于我们是 K8S 集群,所以是被 K8S 发送 kill 命令杀掉的,K8S 杀掉应用的原因是 OOM。

这个 OOM 不是我们 Java 中常说的那个 OOM 异常,而是 K8S 日志中给出的杀掉这个实例的原因,这个 OOM 的意思是:实例使用内存超过了 K8S 设置的实例内存大小限制,所以 K8S 将这个实例给杀掉了。

大家可以先思考一下这个场景,然后想一下自己的排查思路~

我同事判断这是内存泄露,但是正常 JVM 内存泄露它死亡前会生成一个 dump 文件,我们一开始没有拿到这个文件,因为在没有完全生成这个文件的时候 K8S 就把实例杀了(Dump 是单线程的,所以会耗时过长)。

后来我们终于拿到这个文件之后,开始了排查,然后还真的找到了几处内存泄露的地方做了优化。

但是事情远没有结束,做完优化只是延长了这个实例存活的时间,过一段时间以后依然会被 K8S 以 OOM 的原因 Kill 掉。

后来我同事由于太忙(一直没能彻底解决🤣),就委托我来开始排查,这才开始了我的排查之路~

😨内存一切正常?

开始接手排查后,我做的第一件事是问运维要了 gclog, 然后通过 GcEasy 进行在线日志分析,GcEasy 的使用比较简单,只需要将自己的 gclog 文件上传给它:

Image.png

然后点击分析就可以即时生成一个 gclog 图表,类似下面这样的:

Image.png

Image.png

如果有一些比较明显的问题,GcEasy 的报告中还会直接提醒你出现了 memory problem。

在我的这个场景中,我只需要关注下面几个指标就可以了:

  1. gc 平均耗时与最大耗时。
  2. gc 的内存回收曲线图。

GC 的平均耗时与最大耗时是来评估应用是否会发生明显卡顿,如果 gc 有长耗时,则应用一定会卡顿。

如果 gc 的某一次 FullGC 耗时过长则可能会影响 K8S 对此应用是否健康的判断,所以这点是我需要关注的。

第二个就是 gc 内存回收曲线, 因为应用往往是运行一段时间后才死掉,所以推测是不是由于内存泄漏导致大量对象得不到回收,一直被留在 Old 区域中,最终在 FullGC 也无法有效回收 Old 区域的情况下,一波业务流量高峰导致了JVM OOM, 然后在 OOM Dump的过程中导致宿主机也内存不足,最终触发 K8S 的OOM 导致被 Kill 掉。

虽然第二种推测的可能性更大一些,但是也有可能JVM 应用在还没触发宿主机的 OOM 就被宿主机的内核杀掉了。

所以不出乎我意料的是,这两个问题都没有出现,一是 gc 耗时并不长, young 区大概 50-150ms,old 区也不超过 1s。

二是在应用被干掉的前一刻,young 区和 old 区的内存都还有一半的空余(因为每次回收都能回收大量对象,Old 区也没有内存泄漏)~

排除了这两个可能后,内存问题很明显在直接内存区域(或者说非堆内存区域)。

所以我开始通过 GcEasy 的报告来查看 MetaSpace 当前的申请值,遗憾的是,它也远没有达到阈值。

当时问题排查到这里,排查思路就要换一下了,我的大脑中开始疯狂搜索有没有在代码中使用 JDK 的 NIO,或者是其他一些申请堆外内存的地方。

但是作为业务开发来说,我们一般是不会直接使用堆外内存的,使用 NIO 的只有一些常用的 Web 框架,所以我暂时排除了代码问题,打算直接开始分析堆外内存的变化。

🤔Native Memory Tracking

思索了一番后,我决定使用 Native Memory Tracking (下文简称 NMT)进行堆外内存的排查,这是一个 JVM 官方的监控与分析工具,它被直接集成在 JVM 中,虽然它并不能统计到 JDK API 申请内存的操作(比如:DirectBuffer),但是在这一步,我还是打算先使用它观察,因为它方便。

由于使用它对应用性能具有一定影响,所以默认是关闭状态,需要通过 JVM 参数打开。

我们可以通过以下两个参数进行打开:

-XX:NativeMemoryTracking=summary
-XX:NativeMemoryTracking=detail

一般使用第一个即可,第二个具有较大的性能影响,也并不适合我们排查问题。

注:此参数不能通过 jcmd 进行动态打开,需要在启动应用时带上此参数。

由于我们使用它时只能打印当前的应用状态,所以我将通过一个定时脚本的方式持续打印应用的内存情况:

@Scheduled(cron = "0 0/5 * * * ?")
    public void nativeMemoryPrint() {

        String host = "";

        try {
            host = InetAddress.getLocalHost().getHostAddress();

            String pid = ManagementFactory.getRuntimeMXBean().getName().split("@")[0];

            String rollup = Files.readAllLines(Paths.get("/proc/" + pid + "/smaps_rollup"))
                    .stream()
                    .collect(Collectors.joining("\n"));

            log.info("{} 容器实例内存监控 pod : {}", host, rollup);

            Process exec = Runtime.getRuntime().exec(new String[]{"jcmd", pid, "VM.native_memory"});

            String nativeMemoryLog = new BufferedReader(new InputStreamReader(exec.getInputStream())).lines().collect(Collectors.joining("\n"));

            log.info("{} 容器实例内存监控 JVM 进程 : {}", host, nativeMemoryLog);

        } catch (IOException e) {
            log.error("{} 容器实例内存监控出错 : {}", host, e.getLocalizedMessage());
            e.printStackTrace();
        }
    }

注:这个脚本原型来自张哈希张哥,我这里做了一些修改就直接使用了~

通过上面的例子可以看到我使用了两个命令,jcmd 用来打印 JVM 应用的 NMT 信息,使用 smaps_rollup 观测了具体占用。

之所以要加上 smaps_rollu是因为 NMT 打印的结果由于 JVM 内存分配机制的原因不够完全准确,这时候要看实际占用的内存。

通过这两个数据对比着看,来观测是不是进程内存超出了分配内存大小。

先来看看smaps_rollup 的打印:

> cat /proc/23/smaps_rollup 
689000000-fffff53a9000 ---p 00000000 00:00 0                             [rollup]
Rss:             5870852 kB
Pss:             5849120 kB
Pss_Anon:        5842756 kB

这里我们着重来看 Pss 的值即可,可以把它理解为进程实际占用内存大小。

再来看看 NMT 的打印:

Total: reserved=10575644KB, committed=443024KB
-                 Java Heap (reserved=8323072KB, committed=192512KB)
                            (mmap: reserved=8323072KB, committed=192512KB) 
 
-                     Class (reserved=1050202KB, committed=10522KB)
                            (classes #15409)
                            (  instance classes #14405, array classes #1004)
                            (malloc=1626KB #33495) 
                            (mmap: reserved=1048576KB, committed=8896KB) 
                            (  Metadata:   )
                            (    reserved=57344KB, committed=57216KB)
                            (    used=56968KB)
                            (    waste=248KB =0.43%)
                            (  Class space:)
                            (    reserved=1048576KB, committed=8896KB)
                            (    used=8651KB)
                            (    waste=245KB =2.75%)
 
-                    Thread (reserved=669351KB, committed=41775KB)

由于 NMT 的打印太长,这里我只截取了一部分,每个指标上面都有一个 reserved 和 committed,reserved 代表了计划申请的内存,committed 代表了实际申请的物理内存,加之 JVM 具有动态回收的特性,它回收的内存可能不会立马还给操作系统,这里会有一点出入。

如果 committed 和 上面的 Pss 都显示如果所要用的内存已经将要超出宿主机内存,那就代表容器宿主机有被 K8S 杀掉的风险。

😤破案

把上面的脚本发布上线之后, 我就开始了静静等待,就像罗辑在等着太阳系外的咒语生效一样。

终于有一天周一上班运维给我说昨晚上容器又被 kill 了,我赶紧去看相关日志,由于我的日志是 5s 一次,所以能清晰的看到容器在死亡之前的内存状态。

最终证明了我的猜想,容器频繁死亡是因为内存不足,但是不是堆内存而是非堆,最终在我给容器加了 2G 内存之后这个问题再也没有出现过。

PS:其实没排查前我就想加,运维不让,他说你得给我一个理由。。。

等等,一般到这里故事还没有结束,接下来我应该分析到底哪个部分出了问题,是元空间?直接内存?线程内存?

但是我没有再分析下去了,因为复现这个问题要等两周的时间,而且通过我现在了解的信息还不足以证明到底是哪里出现了问题。

通过上面的分析,我们现在得知了:堆 + 元空间 + 其他内存区域的总内存占大小,但是我们还有一些是不知道的,就是我在文章开头提到过的:DirectBuffer 和 MappedByteBuffer,但是他们可以被一个 JVM 参数限制:-XX:MaxDirectMemorySize。

所以把这上面的加一块,就是所有的内存占用总大小了吗?仍然不是,这个参数无法限制 Unsafe 分配的内存。

如果想要彻底的排查出来,可能需要花费更多的时间,而现在问题已经解决了。

以问题为导向,解决了问题,就解决了一切。

毕竟 99% 的区域都是可以被 JVM 参数控制的,剩下的,我当时也不想深究了,毕竟上班很忙,程序员的时间可是很宝贵的~


感谢大家能看到这,同时也希望大家能对本篇点点赞,点赞过 100 一周内更新更多高级 Java 知识,有任何问题都可以在评论区一块讨论,祝有好收获。

注:文中的两个打印结果是引用的张哈希张哥的,因为自己懒得跑jvm 了😭,也推荐一下张哈希关于 NMT 的文章,干货满满~