Netty 堆外内存泄漏排查记录

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

背景

线上长连接服务限制了最大可用堆内存为 8G,并且开启了 -XX:+AlwaysPreTouch

image-20200520151731767

如果不开 AlwaysPreTouch,这里就看不出来问题了,最开始我们就已经加了这个参数,所以也是万幸。

由于开启上线一段时间后堆外内存一直在增长:

image-20200520151826987

测试环境没这个问题,但测试环境最近也没在集中测试,行为和线上不能说是一致的,所以不能作为依据:

image-20200520152557419

在压测过程中我们碰到过一次,但由于当时压测用的客户端也有 bug,后面没有出现过了,于是就没有跟进。当时的现象就是内存不断增加直至进程被 OOM Killer 给干掉。

可以用 dmesg -T| grep -E -i -B100 'killed process' 查看系统日志,这里没有保留相关截图,很遗憾。

为了不让线上出现类似事故,我们决定追根究底地排查。

排查

排除 ByteBuf

首先,我们在代码中做了一个简单的堆外内存统计,发现堆外内存并无增加,初步排除了 ByteBuf 相关的泄漏。

image-20200601100201246

如果有 ByteBuf 相关的泄漏,只要有相关的 Metric 报告,也比较好排查,挂一台客户端在线上不断进行 MQTT Publish 业务操作即可看出来。

安装 gperftools

为了跟踪堆外内存的分配,这里要了个 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 一边动态链接库给 ld 用。

指定 heap profile 的路径和前缀(HEAPPROFILE):

export HEAPPROFILE=<base>/<prefix>

启动后,会在 base 生成 <prefix>.xxxx.heap,xxxx 为序号。

image-20200527102101404

pprof 对比 heap

之后就可以使用 pprof 对这些 heap 文件进行分析了:

pprof --text $JAVA_HOME/bin/java <file_name> > out

还可以对比两个 heap,看出差异:

pprof --text --base=<file1_name> $JAVA_HOME/bin/java <file2_name> > compare.out

具体可以使用 pprof --list 看说明。

我们对比 heap,输出为 svg,可视化地查看内存分配:

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

发现有一段内存确实在增长,图中是一天的量:

image-20200521173948579

2 天的量:

image-20200522103155908

pmap 查看来源

pmap 查询申请 0x00007fc9192ae375 这段内存的库:

image-20200521174948946

image-20200522103308424

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

image-20200521180008254

源码在 Github 上。

回溯源码

我们根据日志回溯 netty-tcnative 包相关的源码,这里包含两个部分:加载和使用。

加载

程序启动时 io.netty.handler.ssl.OpenSsl 其会加载上述库:

image-20200521181036987

找寻加载相关动作的源码:

image-20200521182611599

image-20200521182749777

image-20200521182902003

往上追溯日志可以看到:

image-20200521183145547

查看源码:

image-20200521183308702

可以看出,Netty 的策略是:如果在 java.library.path 中找不到对应的 .so 文件,则自己从 Jar 包中拷出来输出到临时目录,之后加载到内存。

在 -Djava.io.tmpdir 指定的临时目录创建该文件:

image-20200521183442240

输出流:

image-20200521183550342

加载到内存:

image-20200521183250914

成功:

image-20200521183625960

于是有了第一行的输出:

2020-05-21 18:09:59,706 DEBUG [MqttConnectServer-I/O-Worker-3-1] (i.n.u.i.NativeLibraryLoader:342) - Successfully loaded the library /home/service/app/access-server-mqtt/mhopgup6tjy0/access-server-mqtt-dev-20200520161238/bin/../tmp/libnetty_tcnative_linux_x86_645247644777360469980.so

最终的加载还是使用 JDK 提供的 JNI 方法,即 java.lang.System#load

image-20200521183925487

使用

好了,加载的代码找到了,现在我们来查找使用此库的代码。

image-20200521184714510

可以看到,SSL 相关的 native 方法均由该库提供。

安装“另一个 pprof”

现在我们需要明确这段内存的方法名,查看 pprof 的版本,发现还有另一个 Google 维护的 仓库,其提供 Symbolization 相关的 demangle 功能。

Google 牛逼。

我们安装 golang(需要 1.13 以上)后运行 go get -u github.com/google/pprof,然后使用 /home/gopath/bin/pprof

Go 安装只是一种方式。

运行后发现报错:

image-20200522105535253

输出有提醒我们:这两个 .so 被删除了,所以 load 不了。

Netty 默认会在加载完 .so 后将其从临时目录删除,可以配置 -Dio.netty.native.deleteLibAfterLoading 来改变行为。

我们手动添加回这两个 .so 到 tmp 中并重命名:

image-20200522110424020

再次执行:

/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 申请的内存:

image-20200522111426335

image-20200522110343802

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

image-20200527104253283

提出疑问

但是从日志上看,实际上我们的 连接数并没有变化,那为什么 OPENSSL_malloc 申请的内存会不断增长呢?

再次回到源码

回查 netty-tcnative 源码:

image-20200522112307175

线上使用的是 2.0.27.Final 版本。

pprof 的输出中,我们看到,调用 OPENSSL_malloc 的方法是 netty_internal_tcnative_SSL_newSSL,从命名可以直接看出其对应的 Java 全限定名 io.netty.internal.tcnative.SSL#newSSL,查看 SSL.java:

image-20200522112344487

SSL.c 中的实现如下:

image-20200522112356401

可以看到,确实有通过 OPENSSL_malloc 申请内存的地方,比如创建 tcn_ssl_state_t 结构体时:

image-20200522112842311

64 位下每次 newSSL 申请 32 bytes 内存:

image-20200522112943332

还有其他调用,具体就不看了。

我们回到更熟悉的 Java 代码,调用 newSSL() 的地方有两个:

image-20200522113650874

其中,OpenSsl 里的调用只在类加载时触发一次(静态代码块),除非有通过 ClassLoader 去 hot reload,否则只会申请一次,先排除。

剩下就是 io.netty.handler.ssl.ReferenceCountedOpenSslEngine 了。

到底是那个 SslEngine?

看来关键点在 SSLEngine,那么我们是什么时候用到 javax.net.ssl.SSLEngine 的呢?而这个 SSLEngine 的具体实现类是哪个呢?

查看使用到 SSLEngine 的源码:

image-20200527105737708

image-20200527110028623

可以看到,每次建立连接后,根据 ChannelInitializer 的逻辑来初始化 ChannelHandlerContext 上下文内的流水线时会调用。

而 SslHandler close 时其持有的 SslEngine 会一同关闭:

image-20200527111001470

image-20200527111035737

这里有两个 close 动作(closeInbound()closeOutbound()),这里只列了一个示意。

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

SslContextBuilder 这个建造者设置使用的 SSL 提供方是 SslProvider.OPENSSL,之后生产对应的 io.netty.handler.ssl.SslContext 实现类为 io.netty.handler.ssl.OpenSslServerContext:

image-20200522143001712

那这个 OpenSslServerContext 的 newHandler() 方法生成的 SslHandler 里包裹的那个 SslEngine 到底是哪个实现类呢?

继续查看源码:

image-20200527111608869

从截图还可以看到,这个 OpenSslContext 的回收比较“曲折”,需要从 Finalizer 那里兜一圈(finalize() 方法),堆外内存也是 Finalizer 来释放的(OpenSsl.releaseIfNeeded()),这个后面会提到,先留个印象。

finalize 方法在 JDK 9 被标为 @Deprecated 了,这里的 Project 用的 Java 8,所以方法上没有“删除线”。

原来我们使用的是 OpenSslEngine。

申请时机

查看 OpenSslEngine 继承体系:

image-20200527113055761

本身代码也很简单:

image-20200527113146046

也重写了 finalize() 方法。

在构造器链中,我们找到了 newSSL() 被调用的时机:

image-20200527113325418

释放时机

查看 finalize() 方法里的调用:

image-20200527113910119

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

image-20200527114046572

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

image-20200527114117755

image-20200527114206347

看来是留了个模板方法,也就是说最终会调用 deallocate()

我们最终在 shutdown() 中看到了释放堆外相关的代码:

image-20200527114307800

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

阶段总结一下:

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

猜想

这里关于“为什么没有释放堆外内存”提出几个猜想:

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

排除猜想一、二

前两个猜想都可以简单的通过 dump 内存来分析确定。

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

加 “live” 会触发 Full GC,否则得到的堆中可能存在大量可被下次 GC 回收的对象。

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

image-20200525124607650

image-20200525125106785

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

image-20200527153736462

这些对象的 destroyed 为 true:

image-20200527153913959

image-20200527153812488

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

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

我们换到线上生产环境。

首先,我们确认线上无 Mixed GC:

image-20200525130409170

两次 FullGC 的前后对比:

image-20200525145023305

dump 时连接数为 30 个。

这里不推荐在线上直接 dump,这里由于产品还在内测期间,连接数不多,所以就大胆 dump 了。

这里有个疑问,“为什么第二次 GC 后剩下 263 个而不是 30 个”,这是因为有些 destroyed 已为 true,如果我们过滤 destroyed 为 FALSE 的 OpenSslEngine 个数,正好是 30 个:

image-20200527160456639

所以,如果一个连接连的时间足够长,其对应的 OpenSslEngine 对象已经成功晋升 Old Gen,那么在一个一直没有 Mixed GC 被触发的线上环境,是很可能堆外溢出的。

我们堆外和堆内的配比接近 1:1,那么,只要 OpenSslEngine 在堆外申请的内存远大于其在堆内占用的内存,这种情况就很有可能发生。

这里作为一个优化项日后完善。

可是,在 dump 两次后,线上的内存曲线却没有变化:

image-20200527161029304

dump 时间点大约为 12 点左右。

这样,基本可以确定猜想一、二不成立。

验证猜想三

我们查看 SSL.freeSSL() 源码。

image-20200527165332380

image-20200527165426049

看来这里通过 SSL_free 释放了 ssl 结构。

image-20200527165817439

我们看看 OPENSSL_malloc() 的 API 说明:

image-20200527170110381

看来还应该调 OPENSSL_free() 才对啊?查看 free_ssl_state() 发现“好像”有相应逻辑:

image-20200527170259795

但是这里只释放了 verify_config,state 本身呢?

之前 reset 到了我们使用的 2.0.27.Final,现在我们 pull 一下源码看看有没有修改:

image-20200527170430441

果然……

查看相应 issue:

image-20200527170457704

image-20200527170536727

image-20200527170649465

果然是个 bug,其在 2.0.30.Final 被修复了。

起初,由于 SSL 的代码中关于当前会话状态相关的这部分代码不太好维护,Netty 的开发者打算做一些小重构,结果重构过程中 bug 出现了。

image-20200527170807874

链接如下:https://github.com/netty/netty-tcnative/pull/498

看起来 2.0.27.Final~2.0.29.Final 都有这个问题?我们将版本替换为 2.0.30.Final,问题解决:

image-20200528094105675