jdk17 下 netty 导致堆内存疯涨原因排查 | 京东云技术团队
背景:
介绍
天网风控灵玑系统是基于内存计算实现的高吞吐低延迟在线计算服务,提供滑动或滚动窗口内的 count、distinctCout、max、min、avg、sum、std 及区间分布类的在线统计计算服务。客户端和服务端底层通过 netty 直接进行 tcp 通信,且服务端也是基于 netty 将数据备份到对应的 slave 集群。
低延迟的瓶颈
灵玑第 1 个版本经过大量优化,系统能提供较大的吞吐量。如果对客户端设置 10ms 超时,服务端 1wqps/core 的流量下,可用率只能保证在 98.9%左右,高并发情况下主要是 gc 导致可用率降低。如果基于 cms 垃圾回收器。当一台 8c16g 的机器在经过第二个版本优化后吞吐量超过 20wqps 的时候,那么大概每 4 秒会产生一次 gc。如果按照一次 gc 等于 30ms。那么至少分钟颗粒度在 gc 时间的占比至少在(15*30/1000/60)=0.0075。也就意味着分钟级别的 tp992 至少在 30ms。不满足相关业务的需求。
jdk17+ZGC
为了解决上述延迟过高的相关问题,JDK 11 开始推出了一种低延迟垃圾回收器 ZGC。ZGC 使用了一些新技术和优化算法,可以将 GC 暂停时间控制在 10 毫秒以内,而在 JDK 17 的加持下,ZGC 的暂停时间甚至可以控制在亚毫秒级别。实测在平均停顿时间在 10us 左右,主要是基于一个染色指针和读屏障做到大多数 gc 阶段可以做到并发的,有兴趣的同学可以了解下,并且 jdk17 是一个 lts 版本。
问题:
采用 jdk17+zgc 经过相关的压测后,一切都在向着好的方向发展,但是在一种特殊场景压测,需要将数据从北京数据中心同步给宿迁数据中心的时候,发现了一些诡异的事情
服务端容器的内存疯涨,并且停止压测后,内存只是非常缓慢的减少。
相关机器 cpu 一直保存在 20%(已经无流量请求)
一直在次数不多的 gc。大概每 10s 一次
排查之旅
内存泄漏排查
第一反应是遇到内存疯涨和无法释放该问题时,首先归纳为内存泄漏问题,感觉这题也简单明了。开始相关内存泄漏检查:先 dump 堆内存分析发现占用堆内存的是 netty 相关的对象,恰好前段时间也有个同学也分享了 netty 下的不合理使用 netty byteBuf 导致的内存泄漏,进一步增加了对 netty 内存泄露的怀疑。 于是开启 netty 内存泄漏严格检查模式 (加上 jvm 参数 Dio.netty.leakDetection.level=PARANOID),重新试跑并没有发现相关内存泄漏日志。好吧~!初步判定不是 netty 内存泄漏。
jdk 与 netty 版本 bug 排查
会不会是 netty 与 jdk17 兼容不好导致的 bug? 回滚 jdk8 测试发现的确不存在这个问题,当时使用的是 jdk17.0.7 版本。正好官方发布了 jdk17.0.8 版本,并且看到版本介绍上有若干的 Bug Fixes。所以又升级了 jdk 一个小版本,然而发现问题仍然在。会不会是 netty 的版本过低?正好看见 gitup 上也有类似的 issue# https://github.com/netty/netty/issues/6125WriteBufferWaterMark's 并且在高版本疑似修复了该问题,修改了 netty 几个版本重新压测,然而发现问题仍然在。
直接原因定位与解决
经过上述两次排查,发现问题比想象中复杂,应该深入分析下为什么,重新梳理了下相关线索:
发现回滚至 jdk8 的时候,对应宿迁中心的集群接受到的备份数据量比北京中心发送的数据量低了很多
为什么没有流量了还一直有 gc,cpu 高应该是 gc 造成的(当时认为是 zgc 的内存的一些特性)
内存分析:为什么 netty 的 MpscUnboundedArrayQueue 引用了大量的 AbstractChannelHandlerContext$WriteTask 对象,。MpscUnboundedArrayQueue 是生产消费 writeAndFlush 任务队列,WriteTask 是相关的 writeAndFlush 的任务对象,正是因为大量的 WriteTask 对象及其引用导致了内存占用过高。
只有跨数据中心出现该问题,同数据中心数据压测不会出现该问题。
分析过后已经有了基本的猜想,因为跨数据中心下机房延迟更大,单 channel 信道下已经没法满足同步数据能力,导致 netty 的 eventLoop 的消费能不足导致积压。
解决方案:增加与备份数据节点的 channel 信道连接,采用 connectionPool,每次批量同步数据的时候随机选择一个存活的 channel 进行数据通信。经过相关改造后发现问题得到了解决。
根因定位与解决
根因定位
虽然经过上述的改造,表面上看似解决了问题,但是问题的根本原因还是没有被发现
1.如果是 eventLoop 消费能力不足,为什么停止压测后,相关内存只是缓慢减少,按理说应该是疯狂的内存减少。
2.为什么一直 cpu 在 23%左右,按照平时的压测数据,同步数据是一个流转批的操作,最多也就消耗 5%cpu 左右,多出来的 cpu 应该是 gc 造成的,但是数据同步应该并不多,不应该造成这么多的 gc 压力。
3.为什么 jdk8 下不会存在该问题
推测应该是有个 netty eventLoop 消费耗时阻塞的操作导致消费能力大幅度下降。所以感觉还是 netty 的问题,于是开了 netty 的相关 debug 日志。发现了一行关键日志
顺着这条日志找到了本次的问题根因,为什么一个直接内存的构造器不能使用会导致我们系统 WriteTask 消费阻塞, 带着这个目的去查看相关的源码。
源码分析
一) netty 默认会用 PooledByteBufAllocator 来分配直接内存,采用类似 jmelloc 的内存池机制,每次内存不足的时候会通过创建 io.netty.buffer.PoolArena.DirectArena#newChunk 去预占申请内存。
二) allocateDirect()是申请直接内存的逻辑。大致就是如果能采用底层 unsafe 去申请、释放直接内存和反射创建 ByteBuffer 对象,那么就采用 unsafe。否则就直接调用 java 的 Api ByteBuffer.allocateDirect 来直接分配内存并且采用自带的 Cleaner 来释放内存。这里 PlatformDependent.useDirectBufferNoCleaner 是个关键点,其实就是 USE_DIRECT_BUFFER_NO_CLEANER 参数配置
三) USE_DIRECT_BUFFER_NO_CLEANER 参数逻辑配置在 PlatformDependent 类的 static{}里面。
关键逻辑:maxDirectMemory==0 和!hasUnsafe()在 jdk17 下没有特殊配置都是不满足条件的,关键是 PlatformDependent0.hasDirectBufferNoCleanerConstructor 的判断逻辑
四) PlatformDependent0.hasDirectBufferNoCleanerConstructor()的判断是看 PlatformDependent0 的 DIRECT_BUFFER_CONSTRUCTOR 是否 NULL,回到了刚开的 debug 日志,我们是可以看到在默认情况下 DIRECT_BUFFER_CONSTRUCTOR 该构造器是 unavailable 的(unavailable 则为 NULL)。以下代码具体的逻辑判断及其伪代码。
1.开启条件一:jdk9 及其以上必须要开启 jvm 参数 -io.netty.tryReflectionSetAccessible 参数
2.开启条件二:能反射获取到一个 private DirectByteBuffer 构造器,该构造器是通过内存地址和大小来构造 DirectByteBuffer.(备注:如果在 jdk9 以上对 java.nio 有模块权限限制,需要加上 jvm 启动参数--add-opens=java.base/java.nio=ALL-UNNAMED ,否则会报 Unable to make private java.nio.DirectByteBuffer(long,int) accessible: module java.base does not "opens java.nio" to unnamed module)
所以这里我们默认是没有开启这两个 jvm 参数的,那么 DIRECT_BUFFER_CONSTRUCTOR 为空值,对应第二部 PlatformDependent.useDirectBufferNoCleaner()为 false。
五) 现在回到第 2 步骤,发现 PlatformDependent.useDirectBufferNoCleaner()在 jdk 高版本下默认值是 false。那么每次申请直接内存都是通过 ByteBuffer.allocateDirect 来创建。那么到这个时候就已经定位到相关根因了,通过 ByteBuffer.allocateDirect 来申请直接内存,如果内存不足的时候会强制系统 System.Gc(),并且会同步等待 DirectByteBuffer 通过 Cleaner 的虚引用回收内存。下面是 ByteBuffer.allocateDirect 预占内存(reserveMemory)的关键代码。大概逻辑是 触达申请的最大的直接内存->判断是否有相关的对象在 gc 回收->没有在回收则主动触发 System.gc()来触发回收->在同步循环最多等待 MAX_SLEEPS 次数看是否有足够的直接内存。整个同步等待逻辑在亲测在 jdk17 版本最多能 1 秒以上。
所以最根本原因:如果这个时候我们的 netty 的消费者 EventLoop 处理消费因为申请直接内存在达到最大内存的场景,那么就会导致有大量的任务消费都会同步去等待申请直接内存上。并且如果没有足够的的直接内存,那么就会成为大面积的消费阻塞。
六) 虽然我们看到了阻塞的原因,但是为什么 jdk8 下为什么就不会阻塞从 4 步骤中看到 java 9 以下是设置了 DIRECT_BUFFER_CONSTRUCTOR 的,因此采用的是 PlatformDependent.allocateDirectNoCleaner 进行内存分配。 以下是具体的介绍和关键代码
步骤一:申请内存前:通过全局内存计数器 DIRECT_MEMORY_COUNTER,在每次申请内存的时候调用 incrementMemoryCounter 增加相关的 size,如果达到相关 DIRECT_MEMORY_LIMIT(默认是-XX:MaxDirectMemorySize) 参数则直接抛出异常,而不会去同步 gc 等待导致大量耗时。。
步骤二:分配内存 allocateDirectNoCleaner:是通过 unsafe 去申请内存,再用构造器 DIRECT_BUFFER_CONSTRUCTOR 通过内存地址和大小来构造 DirectBuffer。释放也可以通过 unsafe.freeMemory 根据内存地址来释放相关内存,而不是通过 java 自带的 cleaner 来释放内存。
经过上述的源码分析,已经看到了根本原因,就是 ByteBuffer.allocateDirect gc 同步等待直接内存释放导致消费能力严重不足导致的,并且在最大直接内存不足的情况下,大面积的消费阻塞耗时在申请直接内存,导致消费 WriteTask 能力接近于 0,内存从而无法下降
总结
1.流程图:
2.直接原因:
跨数据中心同步数据单 channel 管道同步数据能力不足,导致 tcp 环阻塞。从而导致 netty eventLoop 的消费 WriteTask 任务(WriteAndFlush)中的 write 能力大于 flush 能力,因此申请的大量的直接内存存放在 ChannelOutboundBuffer#unflushedEntry 链表中没法 flush。
3.根本原因:
netty 在 jdk 高版本需要手动添加 jvm 参数 -add-opens=java.base/java.nio=ALL-UNNAMED 和-io.netty.tryReflectionSetAccessible 来开启采用直接调用底层 unsafe 来申请内存,如果不开启那么 netty 申请内存采用 ByteBuffer.allocateDirect 来申请直接内存,如果 EventLoop 消费任务申请的直接内存达到最大直接内存场景,那么就会导致有大量的任务消费都会同步去等待申请直接内存上。并且如果没有释放足够的直接内存,那么就会成为大面积的消费阻塞,也同时导致大量的对象累积在 netty 的无界队列 MpscUnboundedArrayQueue 中。
4.反思与定位问题慢的原因:
默认同步数据这里不会是系统瓶颈,没有加上 lowWaterMark 和 highWaterMark 水位线的判断(socketChannel.isWritable()),如果同步数据达到系统瓶颈应该提前能感知到抛出异常。
同步数据的时候调用 writeAndFlush 应该加上相关的异常监听器(以下代码 2),若果能提前感知到异常 OutOfMemoryError 那么更方便排查到相关问题。
jdk17 下监控系统看到的非堆内存监控并未与系统实际使用的直接内存统计一致,导致开始定位问题无法定位到直接内存已经达到最大值,从而并未往这个方案思考。
相关引用的中间件底层通信也是依赖于 netty 通信,如果有类似的数据同步也可能会触发类似的问题。特别 ump 在高版本和 titan 使用 netty 的时候是进行了 shade 打包的,并且相关的 jvm 参数也被修改,虽然不会触发该 bug,但是也可能导致触发系统 gc。
作者:京东零售 刘鹏
来源:京东云开发者社区 转载请注明来源
版权声明: 本文为 InfoQ 作者【京东科技开发者】的原创文章。
原文链接:【http://xie.infoq.cn/article/ea1e12b2a390498f790986981】。文章转载请联系作者。
评论