一次寻常的堆外内存泄漏排查

背景

最近部门逐渐的将一些老项目迁移到Spring体系下，对于业务复杂的系统这个过程实在让人受苦不少，借助Spring框架和已经建立的微服务体系倒是的确能改善这些老代码。也有一些处理逻辑非常简单的系统只需要稍微修改一下即可继续提供服务，这次出问题的就是一个逻辑上非常简单的系统，JVM启动参数设置了2G的最大堆内存，但在经过短暂的压测后内存占用涨到了5G左右。

qEJzQrA.jpg!mobile

该图片由 ksyfffka07 在 Pixabay 上发布

PS：在记录这篇文章时问题已经被解决，文中用图均为笔者自行复现，可能会出现一点与描述的偏差。之所以标题为“寻常”的堆外内存泄漏，是因为结局让人感到情理之外，意料之中。

一、猜测

由于这个项目的迁移并不是我本人负责，内部的代码一开始也不是很熟悉，只是压测时这个服务部署在了我负责的测试环境中的几台机器，所以第一时间是我开始分析，随后通知同事也开始在代码中寻找可能的异常点。首先从服务器现场开始：

JjINnqe.png!mobile

上图为应用刚刚启动时的资源占用

nM3iMb7.png!mobile

上图为正常服务时的资源占用

用jmeter压一下：

e: 100 Started: 100 Finished: 0
summary +  46772 in 00:00:30 = 1559.2/s Avg:    64 Min:     0 Max:  1070 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要结果 = 697903 in 00:08:04 = 1443.4/s Avg:    69 Min:     0 Max:  5442 Err:     0 (0.00%)
summary = 697903 in 00:08:04 = 1443.4/s Avg:    69 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要结果 +  46700 in 00:00:30 = 1556.7/s Avg:    63 Min:     0 Max:  1046 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要结果 = 744603 in 00:08:34 = 1450.0/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  46700 in 00:00:30 = 1556.6/s Avg:    63 Min:     0 Max:  1046 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 744603 in 00:08:34 = 1450.0/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要结果 +  46945 in 00:00:30 = 1564.9/s Avg:    64 Min:     0 Max:   986 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要结果 = 791548 in 00:09:04 = 1456.3/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  46945 in 00:00:30 = 1564.9/s Avg:    64 Min:     0 Max:   986 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 791548 in 00:09:04 = 1456.3/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要结果 +  47176 in 00:00:30 = 1572.5/s Avg:    63 Min:     0 Max:   978 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
生成概要结果 = 838724 in 00:09:34 = 1462.4/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
summary +  47176 in 00:00:30 = 1572.4/s Avg:    63 Min:     0 Max:   978 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 838724 in 00:09:34 = 1462.4/s Avg:    68 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要结果 +  46890 in 00:00:30 = 1562.9/s Avg:    63 Min:     0 Max:  1062 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary +  46890 in 00:00:30 = 1563.0/s Avg:    63 Min:     0 Max:  1062 Err:     0 (0.00%) Active: 100 Started: 100 Finished: 0
summary = 885614 in 00:10:04 = 1467.4/s Avg:    67 Min:     0 Max:  5442 Err:     0 (0.00%)
生成概要结果 = 885614 in 00:10:04 = 1467.4/s Avg:    67 Min:     0 Max:  5442 Err:     0 (0.00%)
......

不久，内存占用突破了JVM参数限制( 下图为笔者后期复现的情况，没有继续压到更高 )

[java_server@iZm5e8a3w80j********* ***]$ ps -ef |grep [*********]
java_se+ 19307     1 52 09:35 pts/0    01:06:46 java -Xmx2048m -Xms512m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -jar /data/java_server/*********.jar --spring.profiles.active=test *********

mYRJzmI.png!mobile

进入arthas，查看堆区情况：

ruMVJfZ.png!mobile

显然，实际占用的内存远高于堆区内的情况，基本可以断定是堆外内存泄漏。粗略的浏览一下代码，代码质量较差，大部分是很简单的逻辑，完全没有主动涉及到NIO。那么是某个Spring Boot依赖或者Tomcat引起的吗？

二、排查

看到了表面症状，笔者开始着手分析，首先应用启动时没有加 -XX:NativeMemoryTracking=detail 参数，所以不能通过java直接看到内存分布情况，但并不能确定这种情况是可复现的，所以也没有打算直接重启加参数。

pmap查看内存分布情况： pmap -x 19307| sort -k 3 -n -r

[java_server@iZm5e8a3w80jylw*** ***]$ pmap -x 19307| sort -k 3 -n -r
total kB         7107804 3100028 3085344
00000000d5580000  698368  697856  697856 rw---   [ anon ]
0000000080000000  523264  147496  147496 rw---   [ anon ]
0000000001eff000  127628  119200  119200 rw---   [ anon ]
00007f7cd4000000   65536   60984   60984 rw---   [ anon ]
00007f7cbc000000   65532   60296   60296 rw---   [ anon ]
00007f7cb8000000   65532   60284   60284 rw---   [ anon ]
00007f7c80000000   65516   59844   59844 rw---   [ anon ]
00007f7c6c000000   65492   59676   59676 rw---   [ anon ]
00007f7c78000000   65524   58816   58816 rw---   [ anon ]
00007f7cf0000000   65500   58692   58692 rw---   [ anon ]
00007f7c7c000000   65536   58372   58372 rw---   [ anon ]
00007f7c74000000   65536   58164   58164 rw---   [ anon ]
00007f7ca8000000   65532   58012   58012 rw---   [ anon ]
00007f7ca0000000   65528   57552   57552 rw---   [ anon ]
00007f7c84000000   65500   57300   57300 rw---   [ anon ]
00007f7cd8000000   65532   56996   56996 rw---   [ anon ]
00007f7ca4000000   65512   56992   56992 rw---   [ anon ]
00007f7cc4000000   65484   56104   56104 rw---   [ anon ]
00007f7cdc000000   65512   55752   55752 rw---   [ anon ]
00007f7ce0000000   65536   55720   55720 rw---   [ anon ]
00007f7ce8000000   65420   54644   54644 rw---   [ anon ]
00007f7cc0000000   65528   54552   54552 rw---   [ anon ]
00007f7c9c000000   63364   54396   54396 rw---   [ anon ]
00007f7cac000000   65304   54144   54144 rw---   [ anon ]
00007f7cb0000000   65508   53692   53692 rw---   [ anon ]
00007f7c90000000   65516   53588   53588 rw---   [ anon ]
00007f7cd0000000   63620   52376   52376 rw---   [ anon ]
00007f7cb4000000   65528   52344   52344 rw---   [ anon ]
00007f7c70000000   65512   51856   51856 rw---   [ anon ]
00007f7c88000000   65532   51652   51652 rw---   [ anon ]
00007f7c94000000   65504   51372   51372 rw---   [ anon ]

。。。。

发现上面一大堆看起来不正常的64M内存空间，使用strace追踪系统内存申请： strace -f -e "brk,mmap,munmap" -p 19307 （主要的几种内存分配途径）

[java_server@iZm5e8a3w80jylwqc85v5rZ crypto-oom]$ strace -f -e "brk,mmap,munmap" -p 19307
strace: Process 19307 attached with 44 threads
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000
[pid 19663] munmap(0x7f7d0d75a000, 4096) = 0
[pid 19663] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7d0d75a000

无请求的时候很正常，jmeter打开：

BFBFFvV.png!mobile

一些奇怪的内存申请记录开始出现，符合开头描述的一堆64M内存空间，从smaps文件里找到这段内存地址： cat /proc/19307/smaps > smaps.txt

UJfAnee.png!mobile

进入gdb： gdb -p 19307 ，注意从smaps文件里拿出来的是16进制的内存地址，但是在gdb中操作的时候需要为地址加上0x

尝试dump这段内存： dump memory gdb-dump.mem 0x7f7c04000000 0x7f7c04141000

查看内存内容： strings gdb-dump.mem

[java_server@iZm5e8a3w80jylw**** *****]$ strings gdb-dump.mem 
1599
4325625
159
LFMA
LSGGF53W
15996
4325625
15996
LSVFB6
ss23
0q526
LSVFB6
LSVFB61
43256
e.coyot
tProces 
e.coyot
tProces0
ache/co
rState;@
Erro`
le;)V
~Y6     2Y:
LSGGF
LSVFB61

这一段看起来像是请求中的参数（涉及手机号等信息均删减过，非完整信息），而且片段中出现了 "coyot"，看起来是Tomcat中的连接器Coyote，难道真是Tomcat的原因？虽然知道不大可能，但是抱着好奇的心态还是去翻了tomcat项目的issues目录，并没有发现类似的情况，何况jmeter脚本只把吞吐量加到了1000/s ，线上的其他服务可是比这个吞吐量大多了都没出现过问题啊。

回到正题，我们继续从strace给出的信息着手，下面是另一段strace的信息，表示19319号线程正在取消某块64M内存空间的映射

n2uqmyr.png!mobile

那使用jstack dump线程信息看看： jstack 19307 > stack.txt ，将19319转化为16进制: 4B77,进入线程栈搜索：

yqye6vu.png!mobile

嗯？这是一个Finalizer线程？这是哪部分的代码用了finalize方法来释放资源的吗？好一顿找，最终在服务内部发现了两个未手动关闭的流，问题结束。。。

三、探究

笔者当时排查这里，将结论定为"服务内未关闭的流"就开始改代码，最终解决了问题。照着这个思路走下去，我们需要探究的点就从堆外内存泄漏排查变成了“未释放的流会导致堆外内存泄漏吗？”

我相信一些同学会表示比较茫然，从我们初学Java时，各种资料都会告诉我们“最好”及时释放掉使用完成的资源，但是如果使用的流过多而不释放的话会导致什么结果呢？例如这个问题： https://stackoverflow.com/questions/22889075/do-unclosed-streams-cause-memory-leaks-in-java。bmargulies的回答非常准确：

Failing to close a stream is not a memory leak in this sense. Streams that have native resources have finalizers; the GC will eventually close them down. Unless you hold a reference to the unclosed stream it isn't a leak.

事实也的确如此。那么笔者最后的结论是错误的吗？以下给出一些片段性的信息供同学们一起思考。

系统中未关闭流的类为 java.util.zip.GZIPInputStream
《Java核心技术》卷二第二章第一小节的描述：

当你完成对输入／输出流的读写时，应该通过调用close 方法来关闭它，这个调用会释放掉十分有限的操作系统资源。如果一个应用程序打开了过多的输入／输出流而没有关闭，那么系统资源将被耗尽。

《Java核心思想》第二章第七条：避免使用finalize方法

GZIPInputStream 源码片段：

public void close() throws IOException {
        if (!closed) {
            super.close();
            eos = true;
            closed = true;
        }
    }

java.util.zip.Inflater 源码片段：

/**
     * Creates a new decompressor. If the parameter 'nowrap' is true then
     * the ZLIB header and checksum fields will not be used. This provides
     * compatibility with the compression format used by both GZIP and PKZIP.
     * <p>
     * Note: When using the 'nowrap' option it is also necessary to provide
     * an extra "dummy" byte as input. This is required by the ZLIB native
     * library in order to support certain optimizations.
     *
     * @param nowrap if true then support GZIP compatible compression
     */
    public Inflater(boolean nowrap) {
        zsRef = new ZStreamRef(init(nowrap));
    }

    private native static long init(boolean nowrap);

	/**
     * Closes the decompressor and discards any unprocessed input.
     * This method should be called when the decompressor is no longer
     * being used, but will also be called automatically by the finalize()
     * method. Once this method is called, the behavior of the Inflater
     * object is undefined.
     */
    public void end() {
        synchronized (zsRef) {
            long addr = zsRef.address();
            zsRef.clear();
            if (addr != 0) {
                end(addr);
                buf = null;
            }
        }
    }

    /**
     * Closes the decompressor when garbage is collected.
     */
    protected void finalize() {
        end();
    }

private native static void end(long addr);

java.util.zip.Inflater end 的native方法调用底层 Inflater.c 文件部分代码（来自openjdk）：

Java_java_util_zip_Inflater_init(JNIEnv *env, jclass cls, jboolean nowrap)
{
    z_stream *strm = calloc(1, sizeof(z_stream));

    if (strm == NULL) {
        JNU_ThrowOutOfMemoryError(env, 0);
        return jlong_zero;
    } else {
        const char *msg;
        int ret = inflateInit2(strm, nowrap ? -MAX_WBITS : MAX_WBITS);
        switch (ret) {
          case Z_OK:
.....

Java_java_util_zip_Inflater_end(JNIEnv *env, jclass cls, jlong addr)
{
    if (inflateEnd(jlong_to_ptr(addr)) == Z_STREAM_ERROR) {
        JNU_ThrowInternalError(env, 0);
    } else {
        free(jlong_to_ptr(addr));
    }
}

相信聪明的你心中一定有了自己的结论，自己尝试探索收获才是最大的。

四、结语

这一次出现的问题很明显是同事们在迁移老旧代码，以及代码审查时的掉以轻心导致的。还好在测试阶段被发现了，希望同学们多注意代码质量，细节决定成败，写出更加健壮的代码，共勉。如果文中有任何叙述错误或者不当的地方欢迎及时指出。

背景

一、猜测

二、排查

三、探究

四、结语

Recommend

MySQL全面瓦解5：数据操作-DML

ucore操作系统学习(四) ucore lab4内核线程管理

Hive 如何快速拉取大批量数据

一年烧钱超过200亿，爱奇艺恐遭百度放弃

51CTO博客搬家回归啦！

MagSafe 皮革卡包实体店目前有货

今年双十一让我感觉阿里巴巴已经四面楚歌

Golang

C++11多线程编程-std::async

逆流而上的黑胶唱片，数位趋势下的一支奇兵？

About Joyk

一次寻常的堆外内存泄漏排查

背景

一、 猜测

二、排查

三、探究

四、 结语

Recommend

About Joyk

一、猜测

四、结语