【Netty】ByteBuf.release() was not called before it's garbage-collected

1 現象

• 線上應用運行一段時間就發生應用重啟，臨時調整內存大小，降低重啟頻率，給定位問題和修復缺陷騰點時間，對業務使用降低影響(重啟存在短時不可用狀態，秒級別)；
• 線上使用過程中發現文件無法上傳；文件下載沒問題；業務增刪改查使用正常；
• 日志報錯：
  • 提示無法申請直接內存，已超出最大可申請的直接內存；
  • 提示存在垃圾回收前ByteBuf未釋放；

2021-02-18 16:17:58.399	2021-02-18 16:17:58.399 ERROR 1 --- [oServerWorker-2] c.c.c.g.p.i.ClientToProxyConnection : (AWAITING_INITIAL) [id: 0xedf191be, L:/172.30.173.45:8080 - R:/172.30.146.1:35754]: Caught an exception on ClientToProxyConnection
2021-02-18 16:17:58.399	io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 2781194413, max: 2793406464)
2021-02-18 16:17:58.399	at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:725) ~[netty-all-4.1.42.Final.jar:4.1.42.Final]

2021-02-18 16:33:59.636	2021-02-18 16:33:59.636 ERROR 1 --- [oServerWorker-0] i.n.u.ResourceLeakDetector : LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
2021-02-18 16:33:59.636	Recent access records:
2021-02-18 16:33:59.636	#1:
2021-02-18 16:33:59.636	io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpMessage.release(HttpObjectAggregator.java:379)

2021-02-18 17:13:36.840 ERROR 55896 --- [oServerWorker-3] i.n.u.ResourceLeakDetector               : LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
Created at:
     io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:349)
     io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:187)
     io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:178)
     io.netty.buffer.CompositeByteBuf.allocBuffer(CompositeByteBuf.java:1835)
     io.netty.buffer.CompositeByteBuf.copy(CompositeByteBuf.java:1487)
     io.netty.buffer.AbstractByteBuf.copy(AbstractByteBuf.java:1209)
     io.netty.buffer.WrappedCompositeByteBuf.copy(WrappedCompositeByteBuf.java:493)
	 io.netty.buffer.AdvancedLeakAwareCompositeByteBuf.copy(AdvancedLeakAwareCompositeByteBuf.java:681)
io.netty.handler.codec.http.HttpObjectAggregator$AggregatedFullHttpRequest.copy(HttpObjectAggregator.java:405)
	org.littleshoot.proxy.impl.ClientToProxyConnection.copy(ClientToProxyConnection.java:848)
org.littleshoot.proxy.impl.ClientToProxyConnection.doReadHTTPInitial(ClientToProxyConnection.java:163)
	org.littleshoot.proxy.impl.ClientToProxyConnection.readHTTPInitial(ClientToProxyConnection.java:140)
	org.littleshoot.proxy.impl.ClientToProxyConnection.readHTTPInitial(ClientToProxyConnection.java:56)
	org.littleshoot.proxy.impl.ProxyConnection.readHTTP(ProxyConnection.java:116)
	org.littleshoot.proxy.impl.ProxyConnection.read(ProxyConnection.java:101)
	org.littleshoot.proxy.impl.ProxyConnection.channelRead0(ProxyConnection.java:477)
io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)

2 分析

• Netty依賴於ByteBuf管理直接內存，但ByteBuf的引用由JVM管理，當ByteBuf引用置為空，但實際申請的直接內存未釋放就會導致直接內存溢出；
• 從提示中定位到org.littleshoot.proxy.impl.ClientToProxyConnection.copy方法；查詢Github LittleProxy的issue，也有小伙伴遇到同樣的問題，參考他的實現，不返回copy，而是直接返回original試試看。

3 改造

（1）添加直接內存檢測日志

int maxMemoryInKb = (int) (PlatformDependent.maxDirectMemory() / 1024);
int used = (int) (PlatformDependent.usedDirectMemory() / 1024);
log.info("netty_direct_memory:used({}k) max({}k)", memoryInKb, used, maxMemoryInKb);

（2）ClientToProxyConnection的copy方法修復

private HttpRequest copy(HttpRequest original) {
    if (original instanceof FullHttpRequest) {
        return original; // 注釋掉 ((FullHttpRequest) original).copy();
    } else {
        HttpRequest request = new DefaultHttpRequest(original.protocolVersion(), original.method(), original.uri());
        request.headers().set(original.headers());
        return request;
    }
}

4 本地測試

（1）本地打包應用啟動

java -jar -verbose:gc -Xloggc:/tmp/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -Djava.io.tmpdir=/tmp -XX:OnOutOfMemoryError=$JAVA_HOME/bin/killjava.sh  -XX:+ExitOnOutOfMemoryError -XX:+UseG1GC -Xss228K -Xmx317161K -Xms317161K -XX:MetaspaceSize=64M -XX:MaxMetaspaceSize=64M -Dio.netty.leakDetectionLevel=paranoid -Dio.netty.maxDirectMemory=67108864 gateway-app.jar > log.out

• GC日志打印相關參數：-verbose:gc -Xloggc:/tmp/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -Djava.io.tmpdir=/tmp
• OOM退出參數：-XX:OnOutOfMemoryError=$JAVA_HOME/bin/killjava.sh -XX:+ExitOnOutOfMemoryError
• Netty相關參數：
  • -Dio.netty.leakDetectionLevel=paranoid 溢出檢測級別
    • disabled：禁用；
    • 默認為simple：取樣1%的ByteBuf是否發生泄漏，不打印詳細泄露日志；
    • advanced：取樣1%的ByteBuf是否發生泄漏，打印詳細泄露日志；
    • paranoid：檢測所有的ByteBuf是否發生泄漏，打印詳細泄露日志；（正式上線需去掉，以免影響性能。）
  • -Dio.netty.maxDirectMemory=67108864 Netty最大直接內存設置
    • 參數需實際情況設置，關鍵指標為並發數，Netty性能再高也存在內存正常占用的情況，需要使用完后‘釋放’，所以當並發50與並發100配置的大小差距很大；
    • 默認不配置時，取系統中最大可用的直接內存；
• 分代GC相關參數：-XX:+UseG1GC -Xss228K -Xmx317161K -Xms317161K -XX:MetaspaceSize=64M -XX:MaxMetaspaceSize=64M
• 日志輸出：gateway-app.jar > log.out

注：對溢出檢測感興趣可以看看ResourceLeakDetector、SimpleLeakAwareByteBuf、AbstractByteBufAllocator等幾個類。

（2）壓測

• 使用Jmeter工具模擬文件上傳，並發數緩慢提升，避免直接撐爆最大直接內存，持續壓測30分鍾；
• 使用jvisualvm或jconsole觀察JVM內存狀態，只會發生10多次NewGC；
• 查看log.out日志中，搜索'ERROR'級別日志；（原先版本基本高負載運行5~10分鍾便可以看到內存溢出的提示日志）
• 查看log.out日志中，查看直接內存增長情況；

5 測試環境

（1）提交代碼自動化部署至測試環境

（2）壓測

• 使用Jmeter工具模擬文件上傳，並發數緩慢提升，避免直接撐爆最大直接內存，持續壓測30分鍾；
• 查看log.out日志，搜索'ERROR'級別日志；（原先版本基本高負載運行5~10分鍾便可以看到內存溢出的提示日志）；
• 查看log.out日志中，查看直接內存增長情況；
• jstat -gcutil pid interval：如：jstat -gcutil jvmPid 1000（1號進程每一秒輸出jvm內存狀態，百分比）；
• jstat -gccapacity pid interval：如：jstat -gcutil jvmPid 1000（1號進程每一秒輸出jvm內存狀態，字節數）；
• top 查看進程內存、CPU占用情況；

6 生產上線

• 觀察每天的請求量，請求量與原先差不多，內存短暫飆升后趨於穩定；
• 觀察直接內存使用情況：基本穩定使用163840k/2727936k = 6%；
• 觀察異常日志情況：暫無發現異常；