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。

参考文档

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 216,843评论 6 502
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,538评论 3 392
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 163,187评论 0 353
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,264评论 1 292
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,289评论 6 390
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,231评论 1 299
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,116评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,945评论 0 275
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,367评论 1 313
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,581评论 2 333
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,754评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,458评论 5 344
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,068评论 3 327
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,692评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,842评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,797评论 2 369
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,654评论 2 354

推荐阅读更多精彩内容