一次寻常的堆外内存泄漏排查
- 2020 年 11 月 1 日
- 筆記
背景
最近部门逐渐的将一些老项目迁移到Spring体系下，对于业务复杂的系统这个过程实在让人受苦不少，借助Spring框架和已经建立的微服务体系倒是的确能改善这些老代码。也有一些处理逻辑非常简单的系统只需要稍微修改一下即可继续提供服务，这次出问题的就是一个逻辑上非常简单的系统，JVM启动参数设置了2G的最大堆内存，但在经过短暂的压测后内存占用涨到了5G左右。
该图片由ksyfffka07在Pixabay上发布
PS：在记录这篇文章时问题已经被解决，文中用图均为笔者自行复现，可能会出现一点与描述的偏差。之所以标题为“寻常”的堆外内存泄漏，是因为结局让人感到情理之外，意料之中。
一、 猜测
由于这个项目的迁移并不是我本人负责，内部的代码一开始也不是很熟悉，只是压测时这个服务部署在了我负责的测试环境中的几台机器，所以第一时间是我开始分析，随后通知同事也开始在代码中寻找可能的异常点。首先从服务器现场开始：
上图为应用刚刚启动时的资源占用
上图为正常服务时的资源占用
用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 *********
进入arthas，查看堆区情况：
显然，实际占用的内存远高于堆区内的情况，基本可以断定是堆外内存泄漏。粗略的浏览一下代码，代码质量较差，大部分是很简单的逻辑，完全没有主动涉及到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打开：
一些奇怪的内存申请记录开始出现，符合开头描述的一堆64M内存空间，从smaps文件里找到这段内存地址：cat /proc/19307/smaps > smaps.txt
进入gdb：gdb -p ，注意从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内存空间的映射
那使用jstack dump线程信息看看：jstack 19307 > stack.txt ，将19319转化为16进制: 4B77,进入线程栈搜索：
嗯？这是一个Finalizer线程？这是哪部分的代码用了finalize方法来释放资源的吗？好一顿找，最终在服务内部发现了两个未手动关闭的流，问题结束。。。
三、探究
笔者当时排查这里，将结论定为”服务内未关闭的流”就开始改代码，最终解决了问题。照着这个思路走下去，我们需要探究的点就从堆外内存泄漏排查变成了“未释放的流会导致堆外内存泄漏吗？”
我相信大部分的人都会表示比较茫然，从我们初学Java时，各种资料都会告诉我们“最好”及时释放掉使用完成的资源，但是如果使用的流过多而不释放的话会导致什么结果呢？例如这个问题：//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.Inflaterend 的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)); } }
相信聪明的你心中一定有了自己的结论，自己尝试探索收获才是最大的。
四、 结语
这一次出现的问题很明显是同事们在迁移老旧代码，以及代码审查时的掉以轻心导致的。还好在测试阶段被发现了，希望同学们多注意代码质量，细节决定成败，写出更加健壮的代码，共勉。如果文中有任何叙述错误或者不当的地方欢迎及时指出。
