记一次Netty堆外内存泄漏的排查总结

背景

今年上半年接手了一位离职同事负责的推荐项目，主要是围绕智能推荐服务相关的内容，包括了离线、实时数据处理和线上的预测服务。

这里的堆外内存泄漏也是发生在预测服务这一块，大概的表现情况就是线上服务运行一段时间后，客户端会发生大面积connect reset异常，并且在较短时间内会发生雪崩的情况，下面就简单回顾一下整个问题的排查过程。

环境

该服务运行在公司内部的微服务框架上，这套框架比较久远，依旧是基于HTTP1.X协议进行通信的，传输的序列化用的是google的Gson，Server端基于Netty自研了一套，Client端则是基于okhttp3开发的。

我们服务端目前部署了67台节点，下游调用端超过100台节点。

公司近期做了双中心推广，很多服务都进行了双中心部署。

Server节点配置信息：

8核 13G，系统版本Centos Linux realease 7.8.2003

服务性能指标：

TP99：50ms

TP95：30ms

QPS：2000+（其实不高）

JVM启动参数：
这里就截取部分参数了
-Xms10240m -Xmx10240m -XX:NewSize=3072m -XX:MaxNewSize=3072m -XX:MaxDirectMemorySize=1024m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/skynet-xxx/xxx_heapDump.hprof -XX:+UseParNewGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024M -XX:+ExplicitGCInvokesConcurrent -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=65 -XX:CMSFullGCsBeforeCompaction=2 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/data/logs/skynet-xxx/xxx_gc.log

请求入参上，客户端请求参数大概在mb级别，小点的基本也在数十kb左右，这里入参较大的原因也是业务决定的，单次请求下，用户需要组装的Item集数量很大，并且推荐模型所用到的特征中，实时特征部分也大量依赖了实时的Item业务属性，例如，两程方案按照用户请求动态组合所计算出的特征会依赖Item的具体多个业务属性，因此入参报文大也就可以理解了。

故障

先来看下当天的故障监控

8点半开始，下游调用方开始大面积访问异常，并且出现雪崩的现象，当时9点半收到通知报警（当天正好是周五，美好的周五准备晚点到公司，恰逢高架无限堵车，均速5码，不知道大家能体会笔者当时的心境不，唉，其实当时不光满心都是泪，三急也是呼之欲出的状态，then，N minutes later......）。

到公司那一刻起，开始定位问题，调用方发现大面积抛connect reset

分析

1 查看日志

首先定位服务端日志异常，看下来，并没有发现存在可疑异常，采样了几台节点，通过jstack打印了线程栈，看了下，也并没有看到blocked住的情况。

无奈去查看公共微服务日志文件夹下的日志，结果发现了端倪，Server端大量抛OOM。

2 问题分析

就OOM来看，是源于Netty堆外内存溢出引起的，再看used：1056964615, max：1073741824，已用堆外内存1056964615=1056964615/1024/1024>1008M，而max=1073741824/1024/1024=1024M，Netty再向堆外申请16777216=16777216/1024/1024=16M内存时，明显就不够了，因此抛OOM。

这里回看本文开头提到的JVM启动参数也可以对应起来，-XX:MaxDirectMemorySize=1024m，刚好max也是1024M。

紧接着，我们就去查看了下Netty具体的溢出判定逻辑。

先看PlatformDependent类中的incrementMemoryCounter方法：

Netty源码-PlatformDependent-1

Netty内部通过全局的DIRECT_MEMORY_COUNTER变量来统计应用端已经使用的堆外内存空间，并且DIRECT_MEMORY_COUNTER也被申明为全局静态变量，在allocateDirectNoCleaner和reallocateDirectNoCleaner会做compareAndSet(usedMemory, newUsedMemory)增加动作，如exception则执行decrementMemoryCounter，相当于回滚；在freeDirectNoCleaner也会进行decrementMemoryCounter，归还已经申请的空间。

Netty源码-PlatformDependent-2

其实到这里，业务订单流失的压力已经很大了，为了优先保障业务，这里保留了一台线上故障节点的故障现场，先将所有故障节点进行重启，重启前留了个心，将DIRECT_MEMORY_COUNTER变量进行了监控，监控部分代码也同时上线重启，代码如下：

@Component
public class DirectMemoryReporterImpl {

    private AtomicLong directMemory;

    @PostConstruct
    public void init() {
        Field field = ReflectionUtils.findField(PlatformDependent.class, "DIRECT_MEMORY_COUNTER");
        field.setAccessible(true);

        try {
            directMemory = (AtomicLong) field.get(PlatformDependent.class);
        } catch (IllegalAccessException ignored) {
        }

        ScheduledExecutorService scheduledExecutorService = Executors.newSingleThreadScheduledExecutor();
        scheduledExecutorService.scheduleAtFixedRate(this::doReport, 0, 1, TimeUnit.SECONDS);
    }

    private void doReport() {
        try {
            long memory = directMemory.get();
            SkyLogHelper.traceInfo(LogModule.Monitor, "DirectMemoryReporterImpl", "doReport", "DIRECT_MEMORY_COUNTER -> " + memory + "b", "");
        } catch (Exception e) {
            SkyLogHelper.traceError(LogModule.Monitor, "DirectMemoryReporterImpl", "doReport", "e", "", e);
        }
    }
}

重新部署期间，除了观察线上调用侧的异常指标监控外，又想了下，为什么会有16M的内存申请呢，16M又是哪来的呢，然后继续按照异常栈一步步跟源码，到了PoolArena类的newChunk方法，并且这里的chunkSize是由PoolArena类的allocateNormal传入，这里能看到DirectArena是PoolArena的实现，而调用其构造方法的地方则是PooledByteBufAllocator的初始化方法。

PoolArena

Netty源码-PoolArena-1
Netty源码-PoolArena-2

PooledByteBufAllocator

Netty源码-PooledByteBufAllocator-1
Netty源码-PooledByteBufAllocator-2

validateAndCalculateChunkSize就是计算Chunk大小的方法，通过pageSize页大小和maxOrder深度来计算的，在PooledByteBufAllocator内部也有两个地方有说明，如下：

Netty源码-PooledByteBufAllocator-3
Netty源码-PooledByteBufAllocator-4

具体Netty是如何管理PoolChunk的大家可以参考下这篇文章 [支撑百万级并发，Netty如何实现高性能内存管理]，讲的还是比较不错的，这里就不额外展开了。

我们回到服务，接着聊，生产部署完成后，找了下具体新部署的节点，观察下刚刚上线的DIRECT_MEMORY_COUNTER监控，N hours later......

果然，存在持续缓慢增长的内存泄漏问题，由于项目内部并没有存在持续的基于Netty的IO操作，因此将怀疑点下沉到底层组件。

复现

这里笔者将所有的业务逻辑代码全部注掉，只保留微服务协议接口，方法内部只做了一个Thread.sleep(50);然后返回结果，并将代码在线下本地部署；sdk端使用公司client进行了两轮压测，压测逻辑分别为串行1000次超时200ms的调用和串行1000次1ms超时的调用（这里仅仅只是为了模拟成功和失败的两种场景）；请求入参使用了一个800kb的线上业务实体。

这里为了更便于复现，服务启动时启用了

-Dio.netty.allocator.type=unpooled  使用非Pool池管理
-Dio.netty.leakDetectionLevel=paranoid  启用Netty堆外内存泄漏检测工具，级别=paranoid

有意思的一幕发生了

1000次200ms超时调用：

测试1

1000次1ms超时调用：

测试2

实验2直接Netty检测内存泄漏了，问题到此复现成功。

定位

那么，为什么超时会造成堆外内存泄漏呢，这里我们没有别的办法，只能阅读公司组件源码，找找原因了。

首先看下公司服务端组件Netty相关的初始化动作，它继承了ChannelInitializer，并在初始化阶段追加了自定义的HttpHandler：

HttpHandler继承了ChannelInboundHandlerAdapter，并且使用了CompositeByteBuf，这里由于涉及到公司内部核心组件，因此，只能用伪代码进行展示了，这里我们只截取一些Netty相关通用代码逻辑块：

public class HttpHandler extends ChannelInboundHandlerAdapter {

    private HttpRequest req;

    private final CompositeByteBuf compositeByteBuf = Unpooled.compositeBuffer(32);

    @Override
    public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
        if (msg instanceof HttpRequest) {
            try {
                req = (HttpRequest) msg;
                context = initReq(ctx, msg, req);

                if (!req.decoderResult().isSuccess()) {
                    WriteUtils.write("请求无效， 解码失败", HttpResponseStatus.BAD_REQUEST, context);
                    return;
                }
                。。。
            } catch (Exception e) {
                WriteUtils.write(e.getMessage(), HttpResponseStatus.INTERNAL_SERVER_ERROR, context);
                return;
            }
        }

        if (msg instanceof HttpContent) {
            HttpContent content = (HttpContent) msg;
            ByteBuf bytebuf = content.content();
            compositeByteBuf.addComponent(true, bytebuf);
            if (msg instanceof LastHttpContent) {
                // 校验请求
                if (!validRequest(ctx, context)) return;
                context.getInvocation().setRequestBody(compositeByteBuf.toString(CharsetUtil.UTF_8));
                compositeByteBuf.clear();
                compositeByteBuf.removeComponents(0, compositeByteBuf.numComponents());
                // 具体业务行为传递
                buildChainHandler().handle(context);
            }
        }
    }
    
    。。。
}

看到这里，我们就必须了解下Netty对于Http协议的抽象定义了，推荐这篇文章netty对http协议解析原理解析，这里就简单提下对于Http的几种内容的包装：

  • HttpMethod：主要是对method的封装，包含method序列化的操作

  • HttpVersion: 对version的封装，netty包含1.0和1.1的版本

  • QueryStringDecoder: 主要是对url进行封装，解析path和url上面的参数。(Tips：在tomcat中如果提交的post请求是application/x-www-form-urlencoded，则getParameter获取的是包含url后面和body里面所有的参数，而在netty中，获取的仅仅是url上面的参数)

  • HttpHeaders：包含对header的内容进行封装及操作

  • HttpContent：是对body进行封装，本质上就是一个ByteBuf。如果ByteBuf的长度是固定的，则请求的body过大，可能包含多个HttpContent，其中最后一个为LastHttpContent(空的HttpContent),用来说明body的结束。

  • HttpRequest：主要包含对Request Line和Header的组合

  • FullHttpRequest： 主要包含对HttpRequest和httpContent的组合

Netty-Http生命周期

从生命周期上来讲，HttpRequest -> HttpContent ...... -> LastHttpContent，一个完整的流程。

公司组件的代码中，是将每个HttpContent类型的msg都放入CompositeByteBuf，当到最后一个LastHttpContent到达时，组装CompositeByteBuf中已经写入的所有HttpContent，然后清理CompositeByteBuf中所有的ByteBuf引用，并进行清理（这里的清理也并不是立即执行，而是会等到AbstractReferenceCountedByteBuf中的refCnt下一次变为0时触发deallocate()），再调用业务方法，直到ChannelHandler结束被回收，完成整个生命周期。

那么，如果LastHttpContent没有到来会怎么样呢？

其实这也是timeout=1的那一轮测试所对应的问题了，消息体发送不完整，这里就会存在LastHttpContent逻辑块无法触达的情况，也就是CompositeByteBuf所缓存的ByteBuf引用一直被持有，并且未被执行手动释放操作，那么一直到ChannelHandler生命周期结束，堆外所开辟的空间都将一直被占用，内存泄漏。

到此，我们似乎找到了一个可疑的内存泄漏点，那么如何证明就是它引起的呢？做法也很简单。

    @Override
    public void channelInactive(ChannelHandlerContext ctx) throws Exception {
        logger.info("*** channelInactive");
        super.channelInactive(ctx);
        compositeByteBuf.clear();
        compositeByteBuf.removeComponents(0, compositeByteBuf.numComponents());
    }

在Inative阶段，我们再去手动释放一次CompositeByteBuf，下面来测试一下。

测试3

堆外内存泄漏问题顺利解决。

到此，其实我们已经将问题顺利定位，并提交公共组件负责团队进行确认，并着手修复了。

那我们再回想下，这个场景时线下可以复现的情况下，我们尝试通过测试手段进行场景模拟，然后定位的，那么如果生产环境下，我们会怎么去定位这个问题呢，下面再聊聊当时生产环境战斗的过程，也是异常凶险啊~~

开始下半场正文

由于是Netty堆外溢出，重新部署服务时，笔者保留了一台线上故障节点，可供回溯，就从这台节点入手。

首先期望可以定位到既然堆外内存溢出，那么当时堆外内存泄漏的部分到底是什么内容呢？

这里我们查看了服务进行的内存映射：

jps -m
pmap -pid
163:   java -Duser.timezone=GMT+08 -server -Xms8192m -Xmx10240m -XX:NewSize=3072m -XX:MaxNewSize=3072m -XX:MaxDirectMemorySize=1024m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m-XX:+UseContainerSupport -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/xxx/xxx_heapDump.hprof -XX:+UseParNewGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024M -XX:+ExplicitGCInv
0000000000400000      4K r-x-- java
0000000000600000      4K r---- java
0000000000601000      4K rw--- java
00000000016c0000    132K rw---   [ anon ]
0000000560800000 8388608K rw---   [ anon ]
0000000760800000 2097152K -----   [ anon ]
00000007e0800000   6528K rw---   [ anon ]
00000007e0e60000 1042048K -----   [ anon ]
00007f91b8000000    892K rw---   [ anon ]
00007f91b80df000  64644K -----   [ anon ]
00007f91bc000000    132K rw---   [ anon ]
00007f91bc021000  65404K -----   [ anon ]
00007f91c0000000    800K rw---   [ anon ]
00007f91c00c8000  64736K -----   [ anon ]
00007f91c4000000    980K rw---   [ anon ]
00007f91c40f5000  64556K -----   [ anon ]
00007f91c8000000    916K rw---   [ anon ]
00007f91c80e5000  64620K -----   [ anon ]
00007f91cc000000    608K rw---   [ anon ]
00007f91cc098000  64928K -----   [ anon ]
00007f91d0000000    932K rw---   [ anon ]
00007f91d00e9000  64604K -----   [ anon ]
00007f91d4000000    584K rw---   [ anon ]
00007f91d4092000  64952K -----   [ anon ]
00007f91d8000000    756K rw---   [ anon ]
00007f91d80bd000  64780K -----   [ anon ]
00007f91dc000000   1452K rw---   [ anon ]
00007f91dc16b000  64084K -----   [ anon ]
00007f91e0000000    612K rw---   [ anon ]
00007f91e0099000  64924K -----   [ anon ]

能看到不少anon的64M左右的连续空间，每一组例如892K + 64644K = 65536K 正好是64M，笔者线下也对比了堆外内存泄漏前后相关内存块的变化：

发现所分配的rw内存会持续增长，那么这里就准备查看下这一部分变化的内存中到底是哪些内容。

这里会用到gdb调试工具，如果有c或c++相关基础的同学可以跳过这一部分：

这里附带一份安装指令集：

wget http://mirrors.ustc.edu.cn/gnu/gdb/gdb-7.9.1.tar.xz
tar -xf gdb-7.9.1.tar.xz
cd gdb-7.9.1
yum install texinfo
./configure
// 这里可能会抛异常no termcap library found
// 下载termcap -> https://ftp.gnu.org/gnu/termcap/
mkdir ../termcap
cd ../termcap
wget https://ftp.gnu.org/gnu/termcap/termcap-1.3.1.tar.gz
tar -zxvf termcap-1.3.1.tar.gz
cd termcap-1.3.1
./configure
make
make install
cd ../gdb-7.9.1
make install
gdb -v // 确认安装成功

// 这里如果遇到configure: error: no acceptable C compiler found in $PATH
// 则需要安装gcc
yum install gcc

N minutes later......

我们终于可以开始使用gdb了，let's do it。

// 我们就上面分析的那一块连续的64M内存进行dump快照，查看具体的内容
gdb -p 160
(gdb)dump memory 0x7f91b8000000_0x7f91b80df000.bin 0x7f91b8000000 0x7f91b80df000
(gdb)dump memory 0x7f91b80df000_0x7f91bc000000.bin 0x7f91b80df000 0x7f91bc000000
(gdb)quit

strings 0x7f91b8000000_0x7f91b80df000.bin > 0x7f91b8000000_0x7f91b80df000.log
strings 0x7f91b80df000_0x7f91bc000000.bin > 0x7f91b80df000_0x7f91bc000000.log
less 0x7f91b8000000_0x7f91b80df000.log

终于我们寻根之地，看到了最终的光明圣地，

这不正是我们的请求入参正文么，那我们在:G到最后一行看看，

果然，非正常中断，再看第二个内存块strings后的文件，发现内容为空，文件大小为0，笔者也在线下模拟内存泄漏后进行对比，发现持续的内容也是非正常中断，对应了我们验证的LastHttpContent未到达，且堆外内存未进行回收的结论。

至此，整个Netty堆外内存泄漏的排查定位过程结束。

总结

其实这个问题存在了很长时间，至于到近期爆发，其实也是源于公司双中心机房升级引起的，部分下游服务异地部署，异地服务需要走专线，造成异地服务访问耗时加长，堆外内存泄漏的问题才会被放大。

总的来说，这次故障定位的过程很艰辛，当然，最终的结果也是很棒的。

笔者在此也算沉淀出一些方法论，面对像OOM这样的问题时，首先要先明确，是哪一种OOM，有堆内、堆外、方法区等等，也有启动时阶段或者运行时阶段，首先要明确当下自己的场景，因为不会有人比你更了解你的代码，当你坚定问题方向后，也要义无反顾的坚持下去，总会有自己不在行的领域，只要肯多付出时间、精力，总会有提高和回报。

参考文献

疑案追踪：Spring Boot内存泄露排查记

netty 堆外内存泄露排查盛宴

生活不易、各自努力

前路漫漫，互勉同行

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 194,911评论 5赞 460
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 82,014评论 2赞 371
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 142,129评论 0赞 320
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 52,283评论 1赞 264
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 61,159评论 4赞 357
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 46,161评论 1赞 272
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 36,565评论 3赞 382
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 35,251评论 0赞 253
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 39,531评论 1赞 292
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,619评论 2赞 310
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,383评论 1赞 326
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 32,255评论 3赞 313
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 37,624评论 3赞 299
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 28,916评论 0赞 17
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,199评论 1赞 250
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 41,553评论 2赞 342
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 40,756评论 2赞 335