前言
近期在研究使用Spring Cloud Alibaba
系列套件中的spring-cloud-alibaba-dubbo
开发RESTful接口,从GitHub上获取了官方的examples研究了一下,发现使用该套件借助Nacos
开发微服务接口非常适合。
问题现象
开发完成后,将接口程序制作成镜像,并部署在Docker容器中,做压力测试时发现,控制台日志有些异常:
2020-06-10 03:43:52.519 [ERROR] [nioEventLoopGroup-4-2] [i.n.util.ResourceLeakDetector ] LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
开始没有意识到这将是入坑的开始,压测到容器内存占用达到70%左右时,压测程序会无法收到程序响应。并且,再次请求接口时,控制台打出了如下错误日志:
2020-06-10 02:42:25.337 [WARN ] [nioEventLoopGroup-5-55] [.AbstractChannelHandlerContext] An exception 'java.lang.NullPointerException' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 251658247, max: 259522560)
at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:726)
at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:681)
at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:758)
at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:734)
at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:245)
分析过程
OutOfDirectMemoryError
堆外内存溢出,首先想到借助jmap
生成内存dump文件进行分析,命令如下:
jmap -dump:format=b,file=dump <pid>
拿到dump文件,通过MemoryAnalyzer
工具进行分析,并未看到明显的问题。
接下来,试着在启动容器时,添加以下参数,让报错时的堆栈信息更完整,帮助我们分析问题,同时将堆外内存调到20M,使问题更快发生。
-Dio.netty.leakDetection.level=advanced -Dio.netty.leakDetection.maxRecords=20 -Dio.netty.leakDetection.targetRecords=20 -XX:MaxDirectMemorySize=20M
再次压测后,得到了更加完整的日志信息:
2020-06-10 03:43:52.519 [ERROR] [nioEventLoopGroup-4-2] [i.n.util.ResourceLeakDetector ] LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
#1:
io.netty.handler.codec.http.DefaultHttpContent.release(DefaultHttpContent.java:94)
io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:90)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:326)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:300)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)
io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.lang.Thread.run(Thread.java:748)
#2:
io.netty.buffer.AdvancedLeakAwareByteBuf.order(AdvancedLeakAwareByteBuf.java:70)
io.netty.buffer.CompositeByteBuf.newComponent(CompositeByteBuf.java:335)
io.netty.buffer.CompositeByteBuf.addComponent0(CompositeByteBuf.java:280)
io.netty.buffer.CompositeByteBuf.addComponent(CompositeByteBuf.java:265)
io.netty.buffer.CompositeByteBuf.addComponent(CompositeByteBuf.java:222)
io.netty.handler.codec.MessageAggregator.appendPartialContent(MessageAggregator.java:333)
io.netty.handler.codec.MessageAggregator.decode(MessageAggregator.java:298)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:88)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:326)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:300)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)
io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.lang.Thread.run(Thread.java:748)
(后面省略......)
netty的内存泄漏检测机制帮助我们跟踪到了程序中存在的内存泄漏问题。但是分析完堆栈后发现,并非我们自己的代码导致了错误。
解决
查阅官方资料及源码后发下, 通过dubbo
暴露rest形式的接口,实际上是借助RESTEasy
来实现的。查看所使用的的RESTEasy
系列依赖的版本是3.0.19.Final
,去RESTEasy
官网查看版的Release Notes发现,在3.0.20.Final
版本中,就有一个Bug修复说明:
[RESTEASY-1205] - RestEasy-Netty4: ByteBuf leak in ResteasyHttpRequestDecoder
终于找到根源所在了,于是更换RESTEasy
的依赖版本后,重新压测未出现警告日志,服务未出现不响应的情况。