dubbo扩展http协议后FullGC

问题

dubbo内部定制的版本中,在处理大于10K的包的时候,会出现内存溢出的现象

原因是我们在定制dubbo http协议的时候,使用了jboss包里面的HttpRequestDecoder的http decoder方法来解析http协议内容
该方法在解析非http协议的大内容时,会出现内存溢出的情况

某个服务因为这个问题,出现了full gc 的情况

复现问题

根据描述复现该问题

  1. 指定dubbo版本
  2. dubbo请求,非http请求
  3. 消息体大于10K

jvm堆配置,jmap -heap pid

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 44564480 (42.5MB)
   MaxNewSize               = 715653120 (682.5MB)
   OldSize                  = 89653248 (85.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

构造provider和consumer,然后在consumer的入参约100K,启动tomcat(JVM)的时候添加打印gc详细信息的参数,发起调用的时候观察gc情况

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

第一次调用的时候并没有出现Full GC的情况,想着是不是并发有点小,毕竟线上还是有一定并发量的,所以consumer端启动线程来调用,启动线程个数1、10、100、1000,线程数是1000的时候provider侧出现了FullGC的情况

2018-01-19T21:01:23.758-0800: [GC (Allocation Failure) [PSYoungGen: 454144K->696K(468992K)] 1394833K->1383056K(1867264K), 0.1343399 secs] [Times: user=0.26 sys=0.01, real=0.14 secs] 
2018-01-19T21:01:23.892-0800: [Full GC (Ergonomics) [PSYoungGen: 696K->0K(468992K)] [ParOldGen: 1382359K->940805K(1398272K)] 1383056K->940805K(1867264K), [Metaspace: 52098K->52098K(1097728K)], 0.2305879 secs] [Times: user=0.54 sys=0.01, real=0.23 secs] 
2018-01-19T21:01:24.629-0800: [Full GC (Ergonomics) [PSYoungGen: 464621K->0K(468992K)] [ParOldGen: 1382601K->941472K(1398272K)] 1847223K->941472K(1867264K), [Metaspace: 52098K->52098K(1097728K)], 0.2063340 secs] [Times: user=0.59 sys=0.00, real=0.21 secs] 
2018-01-19T21:01:25.305-0800: [Full GC (Ergonomics) [PSYoungGen: 454693K->0K(468992K)] [ParOldGen: 1383395K->499265K(1398272K)] 1838088K->499265K(1867264K), [Metaspace: 52098K->52098K(1097728K)], 0.1478104 secs] [Times: user=0.34 sys=0.01, real=0.15 secs] 
2018-01-19T21:01:25.945-0800: [Full GC (Ergonomics) [PSYoungGen: 457504K->0K(468992K)] [ParOldGen: 1383424K->499950K(1398272K)] 1840928K->499950K(1867264K), [Metaspace: 52098K->52098K(1097728K)], 0.1390671 secs] [Times: user=0.36 sys=0.00, real=0.14 secs] 
2018-01-19T21:01:26.585-0800: [Full GC (Ergonomics) [PSYoungGen: 456673K->0K(468992K)] [ParOldGen: 1384488K->499639K(1398272K)] 1841162K->499639K(1867264K), [Metaspace: 52098K->52098K(1097728K)], 0.1344279 secs] [Times: user=0.32 sys=0.01, real=0.14 secs] 

jstat -gc pid -t 1s

Timestamp        S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
         1438.8 1024.0 5120.0  0.0    0.0   443392.0 430848.7 1398272.0   478878.3  53464.0 52117.3 6144.0 5945.4   1733   97.928  949   166.820  264.748
         1440.0 1024.0 5120.0  0.0    0.0   443392.0 435843.6 1398272.0  1321492.8  53464.0 52117.3 6144.0 5945.4   1733   97.928  950   166.962  264.889
         1441.0 1024.0 5120.0  0.0    0.0   443392.0 433460.4 1398272.0   900800.9  53464.0 52117.3 6144.0 5945.4   1733   97.928  952   167.226  265.153
         1441.9 1024.0 5120.0  0.0    0.0   443392.0   0.0    1398272.0   479419.0  53464.0 52117.3 6144.0 5945.4   1733   97.928  954   167.491  265.419
         1443.0 1024.0 5120.0  0.0    0.0   443392.0 438270.0 1398272.0  1324328.4  53464.0 52117.3 6144.0 5945.4   1733   97.928  955   167.632  265.560
         1444.0 1024.0 5120.0  0.0    0.0   443392.0 437239.3 1398272.0   902696.2  53464.0 52117.3 6144.0 5945.4   1733   97.928  957   167.902  265.830
         1445.0 1024.0 5120.0  0.0    0.0   443392.0 440249.7 1398272.0  1326030.9  53464.0 52117.3 6144.0 5945.4   1733   97.928  959   168.046  265.974
         1446.0 1024.0 5120.0  0.0    0.0   443392.0 434997.3 1398272.0   903830.7  53464.0 52117.3 6144.0 5945.4   1733   97.928  960   168.341  266.269
         1447.0 1024.0 5120.0  0.0    0.0   443392.0 423591.6 1398272.0   480931.8  53464.0 52117.3 6144.0 5945.4   1733   97.928  962   168.610  266.537

问题原因

发生了FullGC,先拿出现在的Heap Dump看看当前JVM的堆内存使用情况

jmap -dump:format=b,file=dump.bin pid

拿到dump文件,拿到MAT中分析下,在dominator_tree视图中找到占用内存较多的对象,这里是byte数组,接下来找到byte数组属于哪一个类,在byte数据上右键"Path To GC Roots" -> "with all reference"就是下图

看到org.jboss.netty.handler.codec.frame.FrameDecoder#cumulation这个对象很大,这个类是HttpRequestDecoder的超类,接下来就是调试源码,查看为什么这个字段会这么大

找到这个字段的所有引用的地方,查看哪里往byte数组(cumulation这个字段包含一个byte数组)中写,主要是下面两个方法

// 这个方法只是把原来的cumulation和新增的input复合到一个对象中,CompositeChannelBuffer
org.jboss.netty.handler.codec.frame.FrameDecoder#appendToCumulation
// 这个方法会对cumulation重新赋值,并把input写入cumulation中,也就是这个时候byte数组会增大
org.jboss.netty.handler.codec.frame.FrameDecoder#updateCumulation

org.jboss.netty.handler.codec.replay.ReplayingDecoder#messageReceived方法中调用上面这两个方法,ReplayingDecoder是HttpRequestDecoder的超类,在接收到请求的时候会调用messageReceived方法,所以在接收到请求的时候就会向cumulation中写数据。

那么现在问题基本清晰了,不断往byte数组中写数据导致byte数组不断增大,问题应该出在byte数组没有被清空上,所以现在的问题是

为什么cumulation没有被清空?

查找所有cumulation被清空的方法

org.jboss.netty.handler.codec.replay.ReplayingDecoder#cleanup

看看谁调用了这个方法

// 连接断开的时候调用这个方法
org.jboss.netty.handler.codec.frame.FrameDecoder#channelDisconnected
// 连接关闭的时候调用这个方法
org.jboss.netty.handler.codec.frame.FrameDecoder#channelClosed

所以只有在连接断开或者关闭的时候才会清空cumulation,结论已经呼之欲出了,回到一开始出现的问题

  1. dubbo请求,非http请求
  2. 大量并发请求

在接收到dubbo请求的时候,虽然不是http协议,但是还是会执行HttpRequestDecoder这个handler,也就会往cumulation中写数据,但是dubbo协议使用的是长连接(netty维护的长连接),所以dubbo请求的内容都会被加入到cumulation中,直到连接关闭或者断开才会清空,如果并发量大的话就会导致有多个cumulation大对象,如果对空间不够的时候就会引起FullGC。

而http协议一般都是短连接,或者有超时时间(服务端超时或者客户端超时),这样cumulation就会被及时清空,所以http协议不容易出现这种问题,而dubbo协议更容易出现的原因。

解决问题

既然是非http请求就不需要使用HttpRequestDecoder做进一步处理,所以新建一个类HttpRequestWrapDecoder继承自HttpRequestDecoder,重写messageReceived方法,在该方法里面判断是否是http请求,如果是http请求才会进一步处理,否则直接返回不处理,执行pipeline中下一个handler

posted @ 2018-02-05 22:20  lacker  阅读(1707)  评论(0编辑  收藏  举报