Netty内存泄漏问题排查

1. 问题描述

手机收到告警 “主机内存不足, 使用率高达 90.31%, 使用了 3.49G”。线上机器查看日志，显示如下：

2019-05-22 13:42:55,241 WARN  [nioEventLoopGroup-4-4] i.n.c.AbstractChannelHandlerContext:146 - [] [] [bds=] An exception '{}' [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: 2063597575, max: 2068840448)
    at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:640)
    at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:594)
    at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:764)
    at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:740)
    at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:244)
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:214)
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:146)
    at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:324)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:185)
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:176)
    at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:137)
    at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:80)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:122)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
    at java.lang.Thread.run(Thread.java:748)

2.分析

看日志报错原因，内存池中对象被分配使用后未进行回收，导致不断新增对象直至到达JVM限制的临界值。怀疑有堆外内存泄漏，对象没有释放导致的。用命令看下JVM核心参数的配置如下：jps -l 、jmap -heap 15345

$ jmap -heap 15345
Attaching to process ID 15345, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.144-b01

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 786432000 (750.0MB)
   MaxNewSize               = 786432000 (750.0MB)
   OldSize                  = 1361051648 (1298.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 39845888 (38.0MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 398458880 (380.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

进一步查找日志，发现有如下日志，“LEAK: ByteBuf.release() was not called before it's garbage-collected.”。怀疑是ByteBuf没有释放导致的堆外内存持续增加，直至无法分配内存。

2019-05-20 14:27:44,760 ERROR [AsyncHttpClient-2-8] i.n.util.ResourceLeakDetector:171 - [] [] [bds=] LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
2019-05-20 14:27:44,760 INFO  [nioEventLoopGroup-4-8] c.w.o.i.n.CompleteUserInfoHandler:149 - [] [] [bds=] Invoke user center result = CompleteUserInfoHandler.WacUserApiResponse(success=true, errCode=null, errMsg=null, result=1)

使用jmap -histo:live 15345 > a.log 分析目前堆中的对象：
包含对象序号、某个对象示例数、当前对象所占内存的大小、当前对象的全限定名，如下图：

 num     #instances         #bytes  class name
----------------------------------------------
   1:         11309      152795888  [B
   2:        252460       20504272  [J
   3:        252367       16151488  io.netty.buffer.PoolSubpage
   4:         12253        6155712  [Ljava.lang.Object;
   5:         42217        4164088  [C
   6:           163        1078064  [Lio.netty.buffer.PoolSubpage;
   7:          1560        1023360  io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
   8:         41770        1002480  java.lang.String
   9:          8835         985352  java.lang.Class
  10:          1248         818688  io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
  11:         20378         652096  java.util.concurrent.ConcurrentHashMap$Node
  12:          5781         508032  [I
  13:         11192         358144  java.util.HashMap$Node
  14:         22009         352144  java.lang.Object
  15:          3316         291808  java.lang.reflect.Method
  16:          2852         276560  [Ljava.util.HashMap$Node;
  17:           150         267952  [Ljava.util.concurrent.ConcurrentHashMap$Node;
  18:          5750         230000  java.util.LinkedHashMap$Entry
  19:            81         194320  [Ljava.nio.ByteBuffer;
  20:            50         185200  [Ljava.nio.channels.SelectionKey;
  21:          2909         162904  java.util.LinkedHashMap
  22:          4085         130720  com.wac.metric.bds.sdk.common.loader.BdsClassloader$ByteCode
  23:           168         113280  [Lio.netty.util.Recycler$DefaultHandle;
  24:          4630         111120  java.util.ArrayList
  25:           971         108752  java.net.SocksSocketImpl
  26:          2192          87680  java.lang.ref.Finalizer
  27:          1448          84752  [Ljava.lang.String;
  28:          3266          78384  javassist.bytecode.Utf8Info
  29:          1469          70512  java.util.HashMap
  30:            40          68480  [Lio.netty.buffer.PoolSubpage;
  31:          2056          65792  com.codahale.metrics.WeightedSnapshot$WeightedSample
  32:             2          65568  [Lcom.alibaba.fastjson.util.IdentityHashMap$Entry;
  33:            60          62400  [Lio.netty.util.Recycler$DefaultHandle;
  34:          1479          59160  java.lang.ref.SoftReference
  35:          1279          51160  java.util.TreeMap$Entry
  36:          2058          49392  java.util.concurrent.ConcurrentSkipListMap$Node
  37:          2057          49368  java.lang.Double
  38:          2270          48208  [Ljava.lang.Class;
  39:          1472          47104  java.util.Hashtable$Entry
  40:           967          46416  java.net.SocketInputStream
  41:           967          46416  java.net.SocketOutputStream
  42:          1440          46080  io.netty.buffer.PoolThreadCache$SubPageMemoryRegionCache

重现问题

通过设置netty的堆外内存检测级别来重现问题。

java -jar -Dio.netty.leakDetection.level=advanced *.jar

解决方案如下,

        try {
            doHttpRequest(xx);
        } finally {
            ReferenceCountUtil.release(msg);
        }

谁来负责Release？在Netty里，因为Handler链的存在，ByteBuf经常要传递到下一个Hanlder去而不复还，所以规则变成了谁是最后使用者，谁负责释放。另外，更要注意的是各种异常情况，ByteBuf没有成功传递到下一个Hanlder，还在自己地界里的话，一定要进行释放。根据谁最后谁负责原则，每个Handler对消息可能有三种处理方式

• 对原消息不做处理，调用 ctx.fireChannelRead(msg)把原消息往下传，那不用做什么释放。
• 将原消息转化为新的消息并调用 ctx.fireChannelRead(newMsg)往下传，那必须把原消息release掉。
• 如果已经不再调用ctx.fireChannelRead(msg)传递任何消息，那更要把原消息release掉。
  假设每一个Handler都把消息往下传，Handler并也不知道谁是启动Netty时所设定的Handler链的最后一员，所以Netty在Handler链的最末补了一个TailHandler，如果此时消息仍然是ReferenceCounted类型就会被release掉。
  要发送的消息由应用所创建，并调用 ctx.writeAndFlush(msg) 进入Handler链。在每个Handler中的处理类似InBound Message，最后消息会来到HeadHandler，再经过一轮复杂的调用，在flush完成后终将被release掉。
  多层的异常处理机制，有些异常处理的地方不一定准确知道ByteBuf之前释放了没有，可以在释放前加上引用计数大于0的判断避免释放失败；有时候不清楚ByteBuf被引用了多少次，但又必须在此进行彻底的释放，可以循环调用reelase()直到返回true。

参考文档

• Netty官方文档 reference-counted-objects
• 官方文档翻译 引用计数对象
• Netty如何有效规避内存泄漏
• Netty之有效规避内存泄漏