長連線Netty服務記憶體漏失,看我如何一步步捉「蟲」解決

2023-04-23 12:01:43

作者:京東科技 王長春

背景

事情要回顧到雙11.11備戰前夕,在那個風雨交加的夜晚,一個急促的咚咚報警,驚破了電閃雷鳴的黑夜,將沉浸在夢香,熟睡的我驚醒。

一看手機咚咚報警,不好!有大事發生了!電話馬上打給老闆:

老闆說: 長連線嗎?
我說:是的!
老闆說:該來的還是要來的,最終還是來了,快,趕緊先把服務重啟下!
我說:已經重啟了!
老闆說: 這問題必須給我解決了!
我說:必須的!

線上應用長連線Netty服務出現記憶體漏失了!真讓人頭大

在這風雨交加的夜晚,此時,面對毫無頭緒的問題,以及迫切想攻克問題的心,已經讓我興奮不已,手一把揉揉剛還迷糊的眼,今晚又註定是一個不眠之夜!

應用介紹

說起支付業務的長連線服務,真是說來話長,我們這就長話短說

隨著業務及系統架構的複雜化,一些場景,使用者操作無法同步得到結果。一般採用的短連線輪訓的策略,使用者端需要不停的發起請求,時效性較差還浪費伺服器資源。

短輪訓痛點:

  • 時效性差
  • 耗費伺服器效能
  • 建立、關閉連結頻繁

相比於短連線輪訓策略,長連線服務可做到實時推播資料,並且在一個連結保持期間可進行多次資料推播。服務應用常見場景:PC端掃碼支付,使用者開啟掃碼支付頁面,手機掃碼完成支付,頁面實時展示支付成功資訊,提供良好的使用者體驗。

長連服務優勢:

  • 時效性高提升使用者體驗
  • 減少連結建立次數
  • 一次連結多次推播資料
  • 提高系統吞吐量

這個長連線服務使用Netty框架,Netty的高效能為這個應用帶來了無上的榮光,承接了眾多長連線使用場景的業務:

  • PC收銀臺微信支付
  • 聲波紅包
  • POS線下掃碼支付

問題現象

回到線上問題,出現記憶體漏失的是長連線前置服務,觀察線上服務,這個應用的記憶體漏失的現象總伴隨著記憶體的增長,這個增長真是非常的緩慢,緩慢,緩慢,2、3個月內從30%慢慢增長到70%,極難發現

每次發生記憶體漏失,記憶體快耗盡時,總得重啟下,雖說重啟是最快解決的方法,但是程式設計師是天生懶惰的,要數著日子來重啟,那絕對不是一個優秀程式設計師的行為!問題必須徹底解決!

問題排查與復現

排查

遇到問題,毫無頭緒,首先還是需要去案發第一現場,排查「死者(應用範例)」死亡現場,通過在發生FullGC的時間點,通過Digger查詢ERROR紀錄檔,沒想到還真找到破案的第一線索:

io.netty.util.ResourceLeakDetector [176] - LEAK: ByteBuf.release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify the JVM option '-Dio.netty.leakDetection.level=advanced' or call ResourceLeakDetector.setLevel() See http://netty.io/wiki/reference-counted-objects.html for more information.

線上紀錄檔竟然有一個明顯的"LEAK"洩漏字樣,作為技術人的敏銳的技術嗅覺,和找Bug的直覺,可以確認,這就是事故案發第一現場。

我們憑藉下大學四六級英文水平的,繼續翻譯下線索,原來是這吶!

ByteBuf.release() 在垃圾回收之前沒有被呼叫。啟用高階洩漏報告以找出洩漏發生的位置。要啟用高階洩漏報告,請指定 JVM 選項「-Dio.netty.leakDetectionLevel=advanced」或呼叫 ResourceLeakDetector.setLevel()

啊哈!這資訊不就是說了嘛!ByteBuf.release()在垃圾回收前沒有呼叫,有ByteBuf物件沒有被釋放,ByteBuf可是分配在直接記憶體的,沒有被釋放,那就意味著堆外記憶體漏失,所以記憶體一直是非常緩慢的增長,GC都不能夠進行釋放。

提供了這個線索,那到底是我們應用中哪段程式碼出現了ByteBuf物件的記憶體漏失呢?
專案這麼大,Netty通訊處理那麼多,怎麼找呢?自己從中搜尋,那肯定是不靠譜,找到了又怎麼釋放呢?

復現

面對這一連三問?彆著急,Netty的紀錄檔提示還是非常完善:啟用高階洩漏報告找出洩漏發生位置嘛,生產上不可能啟用,並且生產發生時間極長,時間上來不及,而且未經驗證,不能直接生產釋出,那就原生程式碼復現一下!找到具體程式碼位置。

為了本地復現Netty洩漏,定位詳細的記憶體漏失程式碼,我們需要做這幾步:

1、設定足夠小的本地JVM記憶體,以便快速模擬堆外記憶體漏失。
如圖,我們設定設定PermSize=30M, MaxPermSize=43M

2、模擬足夠多的長連線請求,我們使用Postman定時批次發請求,以達到服務的堆外記憶體漏失。

啟動專案,通過JProfilerJVM監控工具,我們觀察到記憶體緩慢的增長,最終觸發了本地Netty的堆外記憶體漏失,本地復現成功:

_那問題具體出現在程式碼中哪塊呢?_我們最重要的是定位具體程式碼,在開啟了Netty的高階記憶體漏失級別為高階,來定位下:

3、開啟Netty的高階記憶體漏失檢測級別,JVM引數如下:
-Dio.netty.leakDetectionLevel=advanced

再啟動專案,模擬請求,達到本地應用JVM記憶體漏失,Netty輸出如下具體紀錄檔資訊,可以看到,具體的紀錄檔資訊比之前的資訊更加完善:

2020-09-24 20:11:59.078 [nioEventLoopGroup-3-1] INFO  io.netty.handler.logging.LoggingHandler [101] - [id: 0x2a5e5026, L:/0:0:0:0:0:0:0:0:8883] READ: [id: 0x926e140c, L:/127.0.0.1:8883 - R:/127.0.0.1:58920]
2020-09-24 20:11:59.078 [nioEventLoopGroup-3-1] INFO  io.netty.handler.logging.LoggingHandler [101] - [id: 0x2a5e5026, L:/0:0:0:0:0:0:0:0:8883] READ COMPLETE
2020-09-24 20:11:59.079 [nioEventLoopGroup-2-8] ERROR io.netty.util.ResourceLeakDetector [171] - LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
WARNING: 1 leak records were discarded because the leak record count is limited to 4. Use system property io.netty.leakDetection.maxRecords to increase the limit.
Recent access records: 5
#5:
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.readBytes(AdvancedLeakAwareCompositeByteBuf.java:476)
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.readBytes(AdvancedLeakAwareCompositeByteBuf.java:36)
	com.jd.jr.keeplive.front.service.nettyServer.handler.LongRotationServerHandler.getClientMassageInfo(LongRotationServerHandler.java:169)
	com.jd.jr.keeplive.front.service.nettyServer.handler.LongRotationServerHandler.handleHttpFrame(LongRotationServerHandler.java:121)
	com.jd.jr.keeplive.front.service.nettyServer.handler.LongRotationServerHandler.channelRead(LongRotationServerHandler.java:80)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	......
#4:
	Hint: 'LongRotationServerHandler#0' will handle the message from this point.
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:1028)
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:36)
	io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.touch(HttpObjectAggregator.java:359)
	......
#3:
	Hint: 'HttpServerExpectContinueHandler#0' will handle the message from this point.
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:1028)
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:36)
	io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.touch(HttpObjectAggregator.java:359)
  ......
#2:
	Hint: 'HttpHeartbeatHandler#0' will handle the message from this point.
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:1028)
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:36)
	io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.touch(HttpObjectAggregator.java:359)
  ......
#1:
	Hint: 'IdleStateHandler#0' will handle the message from this point.
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:1028)
	io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.touch(AdvancedLeakAwareCompositeByteBuf.java:36)
	io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.touch(HttpObjectAggregator.java:359)
  ......
Created at:
	io.netty.util.ResourceLeakDetector.track(ResourceLeakDetector.java:237)
	io.netty.buffer.AbstractByteBufAllocator.compositeDirectBuffer(AbstractByteBufAllocator.java:217)
	io.netty.buffer.AbstractByteBufAllocator.compositeBuffer(AbstractByteBufAllocator.java:195)
	io.netty.handler.codec.MessageAggregator.decode(MessageAggregator.java:255)
  ......

開啟高階的洩漏檢測級別後,通過上面異常紀錄檔,我們可以看到記憶體漏失的具體地方:com.jd.jr.keeplive.front.service.nettyServer.handler.LongRotationServerHandler.getClientMassageInfo(LongRotationServerHandler.java:169)

不得不說Netty記憶體漏失排查這點是真香!真香好評!

問題解決

找到問題了,那我麼就需要解決,如何釋放ByteBuf記憶體呢?

如何回收洩漏的ByteBuf

其實Netty官方也針對這個問題做了專門的討論,一般的經驗法則是,最後存取參照計數物件的一方負責銷燬該參照計數物件,具體來說:

  • 如果一個[傳送]元件將一個參照計數的物件傳遞給另一個[接收]元件,則傳送元件通常不需要銷燬它,而是由接收元件進行銷燬。

  • 如果一個元件使用了一個參照計數的物件,並且知道沒有其他物件將再存取它(即,不會將參照傳遞給另一個元件),則該元件應該銷燬它。

詳情請看翻譯的Netty官方檔案對參照計數的功能使用:

【翻譯】Netty的物件參照計數
【原文】Reference counted objects

總結起來主要三個方式
方式一:手動釋放,哪裡使用了,使用完就手動釋放。
方式二:升級ChannelHandlerSimpleChannelHandler, 在SimpleChannelHandler中,Netty對收到的所有訊息都呼叫了ReferenceCountUtil.release(msg)
方式三:如果處理過程中不確定ByteBuf是否應該被釋放,那交給Netty的ReferenceCountUtil.release(msg)來釋放,這個方法會判斷上下文是否可以釋放。

考慮到長連線前置應用使用的是ChannelHandler,如果升級SimpleChannelHandler對現有API介面變動比較大,同時如果手動釋放,不確定是否應該釋放風險也大,因此使用方式三,如下:

線上範例記憶體正常

問題修復後,線上服務正常,記憶體使用率也沒有再出現因洩漏而增長,從線上我們增加的紀錄檔中看出,FullHttpRequestByteBuf記憶體釋放成功。從此長連線前置記憶體漏失的問題徹底解決

總結

一、Netty的記憶體漏失排查其實並不難,Netty提供了比較完整的排查記憶體漏失工具

JVM 選項-Dio.netty.leakDetection.level

目前有 4 個洩漏檢測級別的:

  • DISABLED - 完全禁用洩漏檢測。不推薦

  • SIMPLE - 抽樣 1% 的緩衝區是否有洩漏。預設

  • ADVANCED - 抽樣 1% 的緩衝區是否洩漏,以及能定位到緩衝區洩漏的程式碼位置

  • PARANOID - 與 ADVANCED 相同,只是它適用於每個緩衝區,適用於自動化測試階段。如果生成輸出包含「LEAK:」,則可能會使生成失敗。

本次記憶體漏失問題,我們通過本地設定洩漏檢測級別為高階,即:-Dio.netty.leakDetectionLevel=advanced定位到了具體記憶體漏失的程式碼。

同時Netty也給出了避免洩漏的最佳實踐

  • 在 PARANOID 洩漏檢測級別以及 SIMPLE 級別執行單元測試和整合測試。

  • 在 SIMPLE 級別向整個叢集推出應用程式之前,請先在相當長的時間內檢視是否存在洩漏。

  • 如果有洩漏,灰度釋出中使用 ADVANCED 級別,以獲得有關洩漏來源的一些提示。

  • 不要將洩漏的應用程式部署到整個群集。

二、解決Netty記憶體漏失,Netty也提供了指導方案,主要有三種方式

方式一:手動釋放,哪裡使用了,使用完就手動釋放,這個對使用方要求比較高了
方式二:如果處理過程中不確定ByteBuf是否應該被釋放,那交給NettyReferenceCountUtil.release(msg)來釋放,這個方法會判斷上下文中是否可以釋放,簡單方便
方式三:升級ChannelHandlerSimpleChannelHandler, 在SimpleChannelHandler中,Netty對收到的所有訊息都呼叫了ReferenceCountUtil.release(msg)升級介面,可能對現有API改動會比較大