记一次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阅读 199,340评论 5 467
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 83,762评论 2 376
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 146,329评论 0 329
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 53,678评论 1 270
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 62,583评论 5 359
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 47,995评论 1 275
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,493评论 3 390
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,145评论 0 254
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,293评论 1 294
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,250评论 2 317
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,267评论 1 328
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 32,973评论 3 316
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,556评论 3 303
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,648评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,873评论 1 255
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,257评论 2 345
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 41,809评论 2 339