Netty 堆外内存泄漏排查记录

2020-06-01

Netty

Netty 项目的堆外内存泄漏排查记录。

背景

线上某 MQTT 长连接服务上线一段时间后堆外内存一直在增长： file

这里之所以肯定地指出增长来自“堆外”，是因为开启了 -XX:+AlwaysPreTouch 参数。

测试环境没这个问题，但测试环境那会儿也没在集中测试使用，故行为和线上不完全一致： file

排查

排除 ByteBuf

首先，我们在代码中做了一个简单的堆外内存统计，发现堆外内存并无增加，初步排除了 ByteBuf 引用导致的泄漏。 file

跟踪内存分配

为了跟踪堆外内存的分配，这里要了个 root 权限，在线上机器安装 gperftools：

yum install libunwind-devel
yum install gcc-c++
wget https://github.com/gperftools/gperftools/releases/download/gperftools-2.7.90/gperftools-2.7.90.tar.gz
tar xf gperftools-2.7.90.tar.gz
cd gperftools-2.7.90
./configure
make
sudo make install

程序运行前添加相关 LD_PRELOAD，将其位置加入 usr_local_lib.conf 中，执行 ldconfig 生效：

export LD_PRELOAD=/usr/local/lib/libtcmalloc.so
sudo echo -e "\n/usr/local/lib" >> /etc/ld.so.conf.d/usr_local_lib.conf
sudo /sbin/ldconfig

TCMalloc 是 Google 开发的内存分配器，它重写了 C 的 malloc() 和 C++ 的 new，用于在 C/C++ 代码中进行内存分配，是一种快速的多线程 malloc 实现。这里简单理解为 Google TCMalloc 加入了埋点方便统计、追踪 malloc 调用。 ld 命令是 GNU 的连接器，ldconfig 用于在默认搜寻目录 /lib 和 /usr/lib 以及动态库配置文件 /etc/ld.so.conf 内所列的目录中搜索出共享动态链接库 lib*.so*，然后创建动态装入程序 ld.so 所需的连接和缓存文件。这里安装 gperftools 后会在 /usr/local/lib 下加入 libtcmalloc.so，我们需要将 /usr/local/lib 作为共享库的目录，重新 load 一遍动态链接库。

指定 heap profile 文件的路径和前缀：

export HEAPPROFILE=<base>/<prefix>

程序启动后，会在 base 生成 <prefix>.xxxx.heap 文件，xxxx 为序号，之后就可以使用 pprof 命令对这些文件进行分析了，详细的命令使用可以 pprof --list 查看，这里举两个例子：

# 跟踪 java 进程内存分配，以文本形式输出 profile 结果
pprof --text $JAVA_HOME/bin/java <file_name> > out
# 对比两个 .heap 文件之间的差异
pprof --text --base=<file1_name> $JAVA_HOME/bin/java <file2_name> > compare.out

找到差异

我们希望可视化地对比 heap 之间的差异：

pprof --functions --svg --base=./perftools.0006.heap $JAVA_HOME/bin/java ./perftools.0022.heap > compare_6_22.svg
pprof --functions --svg --base=./perftools.0006.heap $JAVA_HOME/bin/java ./perftools.0033.heap > compare_6_33.svg

发现有一段内存确实在增长，图中是两天的增量：

file

分析差异来源

我们使用 pmap 查看申请 0x00007fc9192ae375 这段内存的库：

file

可以看到这段内存是 libnetty_tcnative_linux_x86_64127899757084192476.so 这个库申请的，该库来源于 Netty fork 自 Tomcat 的一个项目，该项目提供 SSL 相关的 Native 方法支持，源码在 Github 上。

file

明确来源

程序启动时 io.netty.handler.ssl.OpenSsl 其会加载这个库，日志如下：

file

源码相关在 NativeLibraryLoader，这里不再赘述，逻辑就是会优先在 -Djava.library.path 指定的目录找，找不到则从 Jar 包中拷出来输出到 -Dio.netty.native.workdir、-Djava.io.tmpdir 指定的临时目录，之后使用 java.lang.System#load 加载到内存。所以一般这里看到 Error 不用慌，只要顺着 Error 后面输出的日志找，如果看到最终有 “successfully loaded” 就行。

现在我们需要明确这段内存的方法名，pprof 还有另一个 Google 维护的版本，提供 Symbolization demangle 功能，方便我们找到 方法名，二话不说我们装上：

go get -u github.com/google/pprof

运行后发现报错：

file

提示这两个 .so 被删除了，回顾上文我们在 .heap 文件的文本分析结果里可以看到 .so 后面跟着 (deleted)，确实被删除了，查看源码发现 Netty 默认会在加载完 .so 后将其从临时目录删除，可以通过 -Dio.netty.native.deleteLibAfterLoading 改变这一行为。

这里我不重启了，直接手动添加回来再次执行命令

/home/gopath/bin/pprof -symbolize=demangle=full --functions --svg --base=./perftools.0006.heap $JAVA_HOME/bin/java ./perftools.0033.heap > compare_6_33.svg

终于，我们查到是 OpenSSL 申请的内存：

file

图有点糊，重点在这里：

file

OPENSSL_malloc 这个方法是 OpenSSL 提供的 API，封装了其申请内存相关的操作：

file

提出疑问

但是实际上我们线上的 连接数 并没有变化，为什么 OPENSSL_malloc 申请的内存会不断增长呢？

回溯源码

我们还是回到源码，找到内存申请的位置，这里记得 reset 正在使用的版本 tag（2.0.27.Final）：

file

pprof 的输出中，我们看到，调用 OPENSSL_malloc 的方法是 netty_internal_tcnative_SSL_newSSL，从命名可以直接看出其对应的 Java 代码是 io.netty.internal.tcnative.SSL#newSSL。

file

创建 tcn_ssl_state_t 结构体时有通过 OPENSSL_malloc 申请内存：

file

Java 代码调用 newSSL() 的地方有两个：

file

其中，OpenSsl 里的调用只在类加载时触发一次（静态代码块），除非有 hot reload，否则只会申请一次，先排除，基本明确是 ReferenceCountedOpenSslEngine 了，那么看来关键点在 SSLEngine，我们是什么时候用到 javax.net.ssl.SSLEngine 的，而这个 SSLEngine 的具体实现类是哪个呢？

我回溯自己写的代码：

file

这里有两个 close，closeInbound() 和 closeOutbound()，这里只列了一个示意。

简而言之，就是建连时 new 一个，断连时关掉。

SslContextBuilder 使用的是 SslProvider.OPENSSL，对应的 SslContext 实现类为 OpenSslServerContext：

file

那这个 OpenSslServerContext 的 newHandler() 生成的 SslHandler 里 wrap 的那个 SslEngine 到底是哪个实现类呢？

file

OK，是 OpenSslEngine。

从截图还可以看到，这个 OpenSslContext 的回收比较“曲折”，需要从 Finalizer 那里兜一圈 Object::finalize，堆外内存也是 Finalizer 来释放的（OpenSsl.releaseIfNeeded()），这个后面会提到，先留个印象。顺带一提，finalize() 在 JDK 9 被标为 @Deprecated 了，图中是 Java 8。

file

OpenSslEngine 本身代码也很简单，也重写了 finalize()：

file

在 Constructors 链中，我们找到了 newSSL() 被调用的时机：

file

finalize() 方法里的调用：

file

OpenSslEngine 是 ReferenceCounted 的实现，这里会触发其重写后者定义的 release() 方法。

看来 OpenSslEngine 自己又持有一个 ReferenceCounted 属性 refCnt：

file

模板里留了个方法，也就是说最终会调用 deallocate()，最终我们在 shutdown() 中看到了释放堆外相关的代码：

file

这里的 SSL.freeSSL() 会将之前 newSSL() 时的内存释放掉。

阶段总结一下：

增长的内存是 SSL.newSSL() 申请的堆外内存
只有通过 new 构造 OpenSslEngine 时才会触发
在 GC 分析 OpenSslEngine 不可达后，Finalizer 机制会保证 SSL.freeSSL() 被调用

提出猜想

OpenSslEngine 还有 GC Root 可达，导致其生命周期较长，迟迟不释放
OpenSslEngine 没有 GC Root 可达，但没被 GC 回收
OpenSslEngine 被 GC 回收了，但没成功释放堆外内存

排除部分猜想

我们首先排除了猜想 1 和 2，这个可以简单的通过 dump 内存来分析确定。

jmap -dump:format=b,live,file=dump.hprof <pid>

加 “live” 会立即触发一次 Full GC，不加的话得到的堆中可能存在大量“可被下次 GC 回收”的对象。

我们在测试环境 dump 两次内存，此时的连接数统计为 13 个。

file

可以看到，第一次 dump 得到的 OpenSslEngine 对象个数和此时的连接数相去甚远，很多对象都在 Finalizer 的队列中：

file

这些对象的 destroyed 属性为 true（见 shutdown()）：

file

可以比较清楚的看出 finalize() 方法确实被调用了。

我们还发现这些 OpenSslEngine 对象的 Retained Heap 各不一样，已完成握手的大一些，未开始的小一些。

我们换到线上生产环境。

首先，我们确认线上无 Mixed GC：

file

两次 FullGC 的前后对比：

file

dump 时查看实时统计，发现连接数为 30 个，过滤 destroyed 为 FALSE 的 OpenSslEngine 个数，正好是 30 个：

file

这里不推荐在线上直接 dump，这里由于产品还在内测期间，连接数不多。

如果一个连接连的时间足够长，其对应的 OpenSslEngine 对象已经成功晋升 Old Gen，那么在一个一直没有 Mixed GC 被触发的线上环境，是很可能堆外先溢出的，我们堆外和堆内的配比接近 1:1，那么，只要 OpenSslEngine 在堆外申请的内存远大于其在堆内占用的内存，这种情况就很有可能发生。不过这只是一个“意外收获”，和这次的问题无关，作为一个优化项，日后完善。

在 dump 两次后，线上的内存没有变化，可以确定猜想一、二不成立。