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


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM