研发日记｜一次 Java 乌龙“内存泄露”排查之旅

《研发日记》这个系列的诞生初衷，是希望分享 AutoMQ 版本迭代中我们的研发故事，其中会包括技术调研、问题诊断、性能优化等内容。如果你也对 AutoMQ 背后的技术和进展感兴趣的话，欢迎关注我们。

本文是研发日记的第一篇，分享了 AutoMQ 一起被误诊为内存泄露，但是实际是由于观测方式不当导致的乌龙问题的分析流程，读者可以从中借鉴 Java 应用内存问题的排查手段和我们的排查思路。

前情提要

在经过了九个 RC 版本的迭代后，AutoMQ 在近期推出了 1.0.0 GA 版本。在 AutoMQ GA版本发布之前，我们进行了大量的、长时间运行的测试。某一晚我们自信满满地进行压测时，我们通过 Top 命令发现 Java 进程对内存占用竟高达12GB。在我们的这次测试中，AutoMQ 实际分配了 4GB 的堆大小，虽然有使用堆外内存，但是也不应出现出现如此高的内存占用。因此我们也初步判断，这也许是一个“内存泄露”问题，于是便开始了本文艰辛的乌龙排查之旅，虽然最终证明实际上没有内存问题，只是选取观测的数值不合理造成的乌龙，但是整个排查过程和使用到的技术和工具还是值得分享的。

TIPS：AutoMQ 压测使用的技术栈是 Java 17 + ZGC，本文介绍的方法和思路也适用于排查其他版本 Java 应用的内存泄露问题。

问题诊断

确认引发内存问题的内存区域

当我们发现内存异常占用过高时，我们首先需要确认引发内存问题的内存区域。Java 应用的内存区域可以分为三种类型：

堆内存： Java 对象分配的空间

堆外内存： 方法区、线程栈、Direct Buffer 等占用内存的区域

非 JVM 内存： native library 分配的内存

对于 AutoMQ 的场景我们首要任务是确认问题是由堆内还是堆外内存导致。AutoMQ在JVM 设置中已经启用OOM dump的VM参数
-XX:+HeapDumpOnOutOfMemoryError，因此如果是由于堆内内存引发 OOM ，我们可以在相应目录下看到堆转储文件，然后通过 MAT/JProfiler 等工具对大对象进行引用分析即可得知堆内内存泄露的原因。

在本例中，我们虽然观察到内存异常飙高，但是程序并没有异常日志以及进程退出的情况出现。我们也通过 JVM 的监控确认在进程在运行期间，堆内存使用率几乎没有增长。因此，我们可以得出一个推断：内存的占用问题是由于堆外内存溢出导致。

确认堆外内存溢出的可能原因

根据已有的知识和信息判断，AutoMQ 堆外内存泄露可能发生在以下几种场景：

1.受JVM管理的堆外内存泄露:

• 方法区、线程栈导致的堆外内存泄露: 这种情况会导致 JVM 崩溃并在运行目录下产生 hs_err_pid.log 文件，查看报错的线程栈可以分析出 VM 参数设置不合理或开启线程过多等原因。

• DirectByteBuffer / FileChannel.map 等受JVM管理的对象内存泄露

**2.非JVM管理的堆外内存泄露：**这块主要是操作系统分配的非JVM内存。

接下来，我们首先确认是否是由于 JVM 管理的堆外内存存在泄露。

确认是否为JVM管理的堆外对象导致内存占用

在本次的例子中，我们并没有找到 hs_err_pid.log 文件。在 AutoMQ 中我们使用了 Netty 的 ByteBuf，其底层使用的是 DirectyByteBuffer，会占用堆外内存。因此，我们推测是由于使用 DirectByteBuffer 这些使用堆外内存的对象引发的问题。

验证DirectByteBuffer等对象的内存占用

DirectByteBuffer 等对象虽然在堆外内存上，但是也受 JVM 管控，可以使用 JVM 提供的 Native Memory Tracking 来分析。除了添加之前提到的VM参数 
-XX:MaxDirectMemorySize=size以外，可以额外添加 VM 参数
-XX:NativeMemoryTracking=[off | summary | detail] 来开启 NMT。

这样，重启 AutoMQ 后，即可使用 jcmd 工具来查看 NMT 数据分析受 JVM 管理的堆外内存对象占用内存的趋势：

jcmd <pid> VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]

重启 AutoMQ 后，我们使用 jcmd 获取的NMT 会输出如下报告：

jcmd 1713702 VM.native_memory summary scale=MB
1713702:

Native Memory Tracking:

(Omitting categories weighting less than 1MB)

Total: reserved=207768MB, committed=6213MB
       malloc: 1823MB #670978
       mmap:   reserved=205945MB, committed=4390MB

-                 Java Heap (reserved=196608MB, committed=4096MB)
                            (mmap: reserved=196608MB, committed=4096MB) 

-                     Class (reserved=260MB, committed=14MB)
                            (classes #17028)
                            (  instance classes #16123, array classes #905)
                            (malloc=4MB #74947) 
                            (mmap: reserved=256MB, committed=11MB) 
                            (  Metadata:   )
                            (    reserved=128MB, committed=82MB)
                            (    used=82MB)
                            (    waste=0MB =0.43%)
                            (  Class space:)
                            (    reserved=256MB, committed=11MB)
                            (    used=10MB)
                            (    waste=0MB =4.21%)

-                    Thread (reserved=472MB, committed=50MB)
                            (thread #472)
                            (stack: reserved=471MB, committed=49MB)
                            (malloc=1MB #2839) 
                            (arena=1MB #941)

-                      Code (reserved=248MB, committed=83MB)
                            (malloc=6MB #23199) 
                            (mmap: reserved=242MB, committed=77MB) 

-                        GC (reserved=8336MB, committed=176MB)
                            (malloc=112MB #48322) 
                            (mmap: reserved=8224MB, committed=64MB) 

-                  Compiler (reserved=4MB, committed=4MB)
                            (malloc=4MB #2150) 

-                  Internal (reserved=6MB, committed=6MB)
                            (malloc=6MB #57737) 

-                     Other (reserved=1658MB, committed=1658MB)
                            (malloc=1658MB #613) 

-                    Symbol (reserved=18MB, committed=18MB)
                            (malloc=16MB #432773) 
                            (arena=2MB #1)

-    Native Memory Tracking (reserved=11MB, committed=11MB)
                            (malloc=1MB #7935) 
                            (tracking overhead=10MB)

-        Shared class space (reserved=16MB, committed=12MB)
                            (mmap: reserved=16MB, committed=12MB) 

-            Serviceability (reserved=1MB, committed=1MB)
                            (malloc=1MB #14544) 

-                 Metaspace (reserved=128MB, committed=83MB)
                            (mmap: reserved=128MB, committed=82MB)

TIPS：根据 JDK 和操作系统版本的不同，NMT中 committed 的数值可能会大于等于操作系统计算的 RSS。具体原因和修复方案可以参考 JDK-8191369 和 JDK-8249666

Java 11 之后 DirectByteBuffer 使用的内存被归入 Other 中（之前是 Internal），我们需要关注的是其中的 committed 部分，代表了真实使用的物理内存。从 NMT 的报告中我们发现 Other 实际只占用了 1658MB 的少量内存。至此，我们可以排除是 DirectByteBuffer 这些堆外内存对象导致内存泄露。

佐证不是 DirectByteBuffer 导致内存泄露

为了保证该推断的准确性，我们还采用了 jeprof 和火焰图来佐证以上的推断。Java 默认使用 glibc 的 malloc，我们可以使用 jemalloc 开启分析功能来查看内存分配情况：

apt install libjemalloc-dev
export LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.2
# 每分配 128K 内存记录堆栈信息，每分配 1GB 内存输出到文件
export MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17

重启应用后在运行目录下会生成类似 jeprof…0.i0.heap 的文件，我们可以使用 jeprof 来输出内存分配情况。

jeprof --svg `which java` jeprof*.heap > jeprof.svg

从生成的图中，我们可以看到分配内存占比89%的函数是 Unsafe_AllocateMemory0。由于 jemalloc 不能进一步分析 java 虚拟机的堆栈，我们进一步配合 async-profler 生成火焰图来确定具体是哪些 Java 对象做了堆外内存的分配：

# 可以将 Unsafe_AllocateMemory0 换成其他任何想观测的函数名
./profiler.sh -d <duration> -e Unsafe_AllocateMemory0 -f unsafe_allocate.html <pid>

生成的火焰图中可以看到 Unsafe_AllocateMemory0 分配的内存实际上是 DirectByteBuffer 使用的，这和 NMT 的报告中显示的占用量基本一致，并不是导致内存占用异常的元凶。通过火焰图的诊断，我们进一步确认这次内存占用异常不是由这些受 JVM 管理的堆外内存引起的。

验证操作系统内存分配的影响

通过上述排查流程，我们已经确认了泄露的内存并不受 JVM 的管控，因此推断是由于操作系统内存分配产生的问题。本小节，我们将深入对操作系统内存分配情况进行分析，进一步确认问题的根因。
为了从操作系统层面观测进程的内存分配，我们采用 Linux 自身的proc目录下的统计信息查看进程内存的占用：

cat /proc/2031108/status                  
Name:   java
...
RssAnon:          805844 kB
RssFile:           38036 kB
RssShmem:       12582912 kB

这里我们可以看到AutoMQ 进程占用的 RssShmem 有 12GB 左右。我们需要进一步找到这 12GB 的内存用在了哪里，我们可以使用 pmap 来查看内存分布：

pmap -x 2031108
Address           Kbytes     RSS   Dirty Mode  Mapping
0000040000000000 4194304 4194304 4194304 rw-s- memfd:java_heap (deleted)
0000040100000000 62914560       0       0 -----   [ anon ]
0000080000000000 4194304 4194304 4194304 rw-s- memfd:java_heap (deleted)
0000080100000000 62914560       0       0 -----   [ anon ]
0000100000000000 4194304 4194304 4194304 rw-s- memfd:java_heap (deleted)
0000100100000000 62914560       0       0 -----   [ anon ]

注意：memfd 是 Linux 的一个特性，可以创建一个匿名文件驻留在内存中。这个文件不会出现在文件系统中，只能通过 /proc//fd 查看，映射的内容会在进程退出时被释放
从 pmap 的结果中，我们可以看到 java 堆被映射到了三个虚拟内存地址上：40000000000、80000000000、100000000000。我们应用的堆大小设置为 4G，如果被映射了三次就产生了 12GB 的 RssShmem 占用。为了验证这个猜想，我们 dump 了这三段内存，对其中的内容进行比较：

dd if="/proc/2031108/mem" of="/dev/stdout" bs=1 skip=$((0x40000000000)) count=128 | hexdump
128+0 records in
128+0 records out
128 bytes copied, 0.000292939 s, 437 kB/s
0000000 0001 0000 0000 0000 1550 0000 0003 0000
0000010 e938 0005 0400 0000 e970 0005 0400 0000
0000020 e9c0 0005 0400 0000 0001 0000 0000 0000
0000030 1550 0000 0007 0000 0000 0000 0000 0000
0000040 0000 0000 0000 0000 0000 0000 0000 0000
*
0000070 0001 0000 0000 0000 1550 0000 0020 0000
0000080

dd if="/proc/2031108/mem" of="/dev/stdout" bs=1 skip=$((0x80000000000)) count=128 | hexdump
128+0 records in
128+0 records out
128 bytes copied, 0.000298448 s, 429 kB/s
0000000 0001 0000 0000 0000 1550 0000 0003 0000
0000010 e938 0005 0400 0000 e970 0005 0400 0000
0000020 e9c0 0005 0400 0000 0001 0000 0000 0000
0000030 1550 0000 0007 0000 0000 0000 0000 0000
0000040 0000 0000 0000 0000 0000 0000 0000 0000
*
0000070 0001 0000 0000 0000 1550 0000 0020 0000
0000080

dd if="/proc/2031108/mem" of="/dev/stdout" bs=1 skip=$((0x100000000000)) count=128 | hexdump
128+0 records in
128+0 records out
128 bytes copied, 0.000330489 s, 387 kB/s
0000000 0001 0000 0000 0000 1550 0000 0003 0000
0000010 e938 0005 0800 0000 e970 0005 0800 0000
0000020 e9c0 0005 0800 0000 0001 0000 0000 0000
0000030 1550 0000 0007 0000 0000 0000 0000 0000
0000040 0000 0000 0000 0000 0000 0000 0000 0000
*
0000070 0001 0000 0000 0000 1550 0000 0020 0000
0000080

从内容结果上来看，我们发现这些内容是完全一致的。因此，我们当下得出了一个结论：
正是这三个堆内存映射造成了内存占用飙高的问题。

进一步分析为什么有三次内存映射

我们发现了罪魁祸首，但是还需要进一步分析为什么会出现三次内存映射。AutoMQ 默认使用了 ZGC， ZGC 引入了指针染色技术，即用对象指针中的某几位来作为 GC 标记，这样就不需要额外的对象头空间来记录 GC 标记了。比如我们用 16 进制下的对象指针最高位来作为 GC 标记，那么指向 0x13210 的对象 GC 标记是 0x1，地址是 0x3210。对于计算机来说，可以用掩码实现从对象指针中提取 GC 标记和对象地址：

Pointer value:     0x13210 : 0001 0011 0010 0001 0000
Metadata mask:   & 0xf0000 : 1111 0000 0000 0000 0000
Metadata bits:     0x1     : 0001

Pointer value:     0x13210 : 0001 0011 0010 0001 0000
Address  mask:   & 0x0ffff : 0000 1111 1111 1111 1111
Address bits:       0x3210 :      0011 0010 0001 0000

每次访问对象时，都需要将 GC 标记位清零以得到真实的地址，这是不可忽略的开销。ZGC 使用多重映射技术巧妙的避免了这个问题。考虑到 0x13210、0x23210 都指向同一个对象，那么我们可以将这两个地址映射到同一块物理内存上，这样就可以避免每次访问对象时的掩码操作：

+-----------+ 0x10000
|           |
|        X  | 0x13210 -----+       +----------------------+
|           |               \      |                      |
+-----------+ 0x20000        +---> | X @ offset 0x3210    | 
|           |               /      |                      |
|        X  | 0x23210 -----+       +----------------------+
|           |
+-----------+ 0x30000

我们将堆映射到 0x10000~0x20000 和 0x20000~0x30000 这两个虚拟内存空间上。只要相对于 0x10000 和 0x20000 的偏移量相同，就能访问到同一块物理内存，这是一种空间换时间的做法。实际上浪费的空间是虚拟内存的空间，用页表的开销换取了每次对象访问时的掩码操作，是一个非常值得的 trade off。更详细的设计可以参考 OpenJDK Wiki：https://wiki.openjdk.org/display/zgc/Pointer+Metadata+using+Multi-Mapped+memory

重新审视 Rss_Shmem 指标

至此，我们发现 Rss_Shmem 计算的实际上是三次堆内存映射的合计值。通过进一步学习与研究，我们了解到 Linux 中一个进程占用的内存有多种统计方式，可以分为 VSS、RSS、PSS、USS：

VSS： Virtual Set Size，进程申请的虚拟内存大小

RSS： Resident Set Size，进程的常驻内存大小，包括代码段、堆、栈、共享库、映射文件等

PSS： Proportional Set Size，进程的比例内存大小，RSS 中的共享内存按照比例分摊到各个进程

USS： Unique Set Size，进程独占的内存大小，RSS 中的共享内存不计入 USS

我们可以通过 PSS 来观测真实的内存占用情况，这里使用了 /proc/[pid]/smaps_rollup 来查看 PSS：

cat /proc/2306924/smaps_rollup
5626d2e58000-7ffca670f000 ---p 00000000 00:00 0                          [rollup]
Rss:             3147164 kB
Pss:             1048716 kB
Pss_Anon:            100 kB
Pss_File:             40 kB
Pss_Shmem:       1048575 kB
Shared_Clean:       1324 kB
Shared_Dirty:    3145728 kB
Private_Clean:        12 kB
Private_Dirty:       100 kB
Referenced:      3147164 kB
Anonymous:           100 kB
LazyFree:              0 kB
AnonHugePages:         0 kB
ShmemPmdMapped:        0 kB
FilePmdMapped:         0 kB
Shared_Hugetlb:        0 kB
Private_Hugetlb:       0 kB
Swap:                  0 kB
SwapPss:               0 kB
Locked:                0 kB

这里可以发现 Pss_Shmem 是 Rss_Shmem 的三分之一，即 4GB，符合 Java 进程的正常内存占用。而Top 当中看到的进程内存占用，实际上表示的是 Rss_Shmem，在涉及 ZGC 和内存映射的场景下存在失真。

Rss_Shmem 反映了所有共享内存对物理内存的总体占用，但它不能准确表明单个进程对共享资源的"贡献"或"责任"程度。如果多个进程共享相同的内存区域，那么每个进程的 Rss_Shmem 都会完整地计入这部分内存，导致对物理内存使用的总和被过量计算。

ss_Shmem 提供了一种更加公平和准确的度量方式，可以用来评估单个进程对共享内存的"贡献"。这是因为它将共享内存的占用量按照共享它的进程数进行了平分，避免了内存使用的重复计算。

因此，在我们实际生产应用中，如果需要观测进程实际的真实内存占用，需要查看Pss_Shmem 的值。

总结

本次疑似“内存泄露”的问题，经过一系列排查，最终被确认为一场由于观测了错误的指标引发的乌龙事件，但是背后的排查和学习过程让我们成长了很多 。同时，这也提醒我们，掌握好操作系统原理以及具体指标的含义，才可以让我们真正将所学的知识用好和发挥作用，避免走弯路。

END

关于我们

我们来自 Apache RocketMQ 和 Linux LVS 项目的核心团队，曾经见证并应对过消息队列基础设施在大型互联网公司和云计算公司的挑战。现在我们基于对象存储优先、存算分离、多云原生等技术理念，重新设计并实现了 Apache Kafka 和 Apache RocketMQ，带来高达 10 倍的成本优势和百倍的弹性效率提升。

🌟 GitHub：https://github.com/AutoMQ/automq-for-kafka

💻 官网：https://www.automq.com