作者：鮑鳳其
愛可生 dble 團隊開發成員，主要負責 dble 需求開發，故障排查和社區問題解答。少説廢話，放碼過來。
本文來源：原創投稿
*愛可生開源社區出品，原創內容未經授權不得隨意使用，轉載請聯繫小編並註明來源。
大家在使用 Java NIO 的過程中，是不是也遇到過堆外內存泄露的問題？是不是也苦惱過如何排查？
下面就給大家介紹一個在dble中排查堆外內存泄露的案例。
現象
有客户在使用dble之後，有一天dble對後端MySQL實例的心跳檢測全部超時，導致業務中斷，最後通過重啓解決。
分析過程
dble 日誌
首先當然是分析dble日誌。從dble日誌中可以發現：
- 故障時間點所有後端 MySQL 實例心跳都超時
- 日誌中出現大量“You may need to turn up page size. The maximum size of the DirectByteBufferPool that can be allocated at one time is 2097152, and the size that you would like to allocate is 4194304”的日誌
日誌片段：
//心跳超時
2022-08-15 11:40:32.147 WARN [TimerScheduler-0] (com.actiontech.dble.backend.heartbeat.MySQLHeartbeat.setTimeout(MySQLHeartbeat.java:251)) - heartbeat to [xxxx:3306] setTimeout, previous status is 1
// 堆外內存可能泄露的可疑日誌
2022-08-15 11:40:32.153 WARN [$_NIO_REACTOR_BACKEND-20-RW] (com.actiontech.dble.buffer.DirectByteBufferPool.allocate(DirectByteBufferPool.java:76)) - You may need to turn up page size. The maximum size of the DirectByteBufferPool that can be allocated at one time is 2097152, and the size that you would like to allocate is 4194304通過上面的日誌猜測：
- 所有MySQL 實例超時是很特殊的，可能是由於故障時間發生了長時間停頓的gc
- 而長時間停頓的gc可能是由於堆外內存不夠，大量的業務流量涌進堆內存中，從而導致頻繁的gc
驗證猜想
為了驗證上面的猜想，獲取了dble機器的相關監控來看。
故障時 dble 機器的內存圖：
可以看到確實存在短時間攀升。而 dble cpu 當時的使用率也很高。
再來看 dble 中 free buffer的監控圖（這個指標是記錄dble中Processor的堆外內存使用情況的）：
從圖中可以看到，從dble啓動後堆外內存呈現遞減的趨勢。
通過上面的監控圖，基本可以確認故障發生時的時序關係：
堆外內存長期呈現遞減的趨勢，堆外內存耗盡之後，在dble中會使用堆內存存儲網絡報文。
當業務流量比較大時，堆內存被迅速消耗，從而導致頻繁的fullgc。這樣dble來不及處理MySQL實例心跳的返回報文，就引發了生產上的一些列問題。
堆外內存泄露分析
從上面的分析來看，根因是堆外內存泄露，因此需要排查dble中堆外內存泄露的點。
考慮到dble中分配和釋放堆外內存的操作比較集中，採用了btrace 對分配和釋放的方法進行了採集。
btrace 腳本
該腳本主要記錄分配和釋放的對外內存的內存地址。
運行此腳本後，對程序的性能有 10% - 20% 的損耗，且日誌量較大，由於堆外內存呈長期遞減的趨勢，因此只採集了2h的日誌進行分析：
package com.actiontech.dble.btrace.script;
import com.sun.btrace.BTraceUtils;
import com.sun.btrace.annotations.*;
import sun.nio.ch.DirectBuffer;
import java.nio.ByteBuffer;
@BTrace(unsafe = true)
public class BTraceDirectByteBuffer {
private BTraceDirectByteBuffer() {
}
@OnMethod(
clazz = "com.actiontech.dble.buffer.DirectByteBufferPool",
method = "recycle",
location = @Location(Kind.RETURN)
)
public static void recycle(@ProbeClassName String pcn, @ProbeMethodName String pmn, ByteBuffer buf) {
String threadName = BTraceUtils.currentThread().getName();
// 排除一些線程的干擾
if (!threadName.contains("writeTo")) {
String js = BTraceUtils.jstackStr(15);
if (!js.contains("heartbeat") && !js.contains("XAAnalysisHandler")) {
BTraceUtils.println(threadName);
if (buf.isDirect()) {
BTraceUtils.println("r:" + ((DirectBuffer) buf).address());
}
BTraceUtils.println(js);
}
}
}
@OnMethod(
clazz = "com.actiontech.dble.buffer.DirectByteBufferPool",
method = "allocate",
location = @Location(Kind.RETURN)
)
public static void allocate(@Return ByteBuffer buf) {
String threadName = BTraceUtils.currentThread().getName();
// 排除一些線程的干擾
if (!threadName.contains("writeTo")) {
String js = BTraceUtils.jstackStr(15);
// 排除心跳等功能的干擾
if (!js.contains("heartbeat") && !js.contains("XAAnalysisHandler")) {
BTraceUtils.println(threadName);
if (buf.isDirect()) {
BTraceUtils.println("a:" + ((DirectBuffer) buf).address());
}
BTraceUtils.println(js);
}
}
}
}分析採集的btrace日誌
採集命令：
$ btrace -o 日誌的路徑 -u 11735 /path/to/BTraceDirectByteBuffer.java過濾出分配的堆外內存的地址：
$ grep '^a:' /tmp/142-20-dble-btrace.log > allocat.txt
$ sed 's/..//' allocat.txt > allocat_addr.txt # 刪除前兩個字符過濾出釋放的堆外內存的地址：
$ grep '^r:' /tmp/142-20-dble-btrace.log > release.txt
$ sed 's/..//' release.txt > release_addr.txt # 刪除前兩個字符此時取兩個文件的差集：
$ sort allocat_addr.txt release_addr.txt | uniq -u > res.txt這樣 res.txt 得到的是僅僅分配而沒有釋放的堆外內存（可能會有不準確）
從中任選幾個堆外內存的 address，查看堆棧。排除掉誤記錄的堆棧後，出現最多的堆棧如下：
complexQueryExecutor176019
a:139999811142058
com.actiontech.dble.buffer.DirectByteBufferPool.allocate(DirectByteBufferPool.java:82)
com.actiontech.dble.net.connection.AbstractConnection.allocate(AbstractConnection.java:395)
com.actiontech.dble.backend.mysql.nio.handler.query.impl.OutputHandler.<init>(OutputHandler.java:51)
com.actiontech.dble.services.factorys.FinalHandlerFactory.createFinalHandler(FinalHandlerFactory.java:28)
com.actiontech.dble.backend.mysql.nio.handler.builder.HandlerBuilder.build(HandlerBuilder.java:90)
com.actiontech.dble.server.NonBlockingSession.executeMultiResultSet(NonBlockingSession.java:608)
com.actiontech.dble.server.NonBlockingSession.lambda$executeMultiSelect$55(NonBlockingSession.java:670)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)review 代碼
在通過btrace知道了dble中的泄露點之後，下面就回到dble的代碼中 review 代碼。
首先通過上面的堆棧定位到下面的代碼：
// com/actiontech/dble/backend/mysql/nio/handler/builder/HandlerBuilder.java
public RouteResultsetNode build(boolean isHaveHintPlan2Inner) throws Exception {
TraceManager.TraceObject traceObject = TraceManager.serviceTrace(session.getShardingService(), "build&execute-complex-sql");
try {
final long startTime = System.nanoTime();
BaseHandlerBuilder builder = getBuilder(session, node, false);
DMLResponseHandler endHandler = builder.getEndHandler();
// 泄露點在這，dble 會創建 OutputHandler實例，OutputHandler會分配堆外內存
DMLResponseHandler fh = FinalHandlerFactory.createFinalHandler(session);
endHandler.setNextHandler(fh);
...
RouteResultsetNode routeSingleNode = getTryRouteSingleNode(builder, isHaveHintPlan2Inner);
if (routeSingleNode != null)
return routeSingleNode;
HandlerBuilder.startHandler(fh);
session.endComplexExecute();
long endTime = System.nanoTime();
LOGGER.debug("HandlerBuilder.build cost:" + (endTime - startTime));
session.setTraceBuilder(builder);
} finally {
TraceManager.finishSpan(session.getShardingService(), traceObject);
}
return null;
}
// com/actiontech/dble/backend/mysql/nio/handler/query/impl/OutputHandler.java
public OutputHandler(long id, NonBlockingSession session) {
super(id, session);
session.setOutputHandler(this);
this.lock = new ReentrantLock();
this.packetId = (byte) session.getPacketId().get();
this.isBinary = session.isPrepared();
// 分配堆外內存
this.buffer = session.getSource().allocate();
}通過上面的代碼可以判斷在構造複雜查詢執行鏈的時候會分配堆外內存。
問題到這其實還是沒有解決，上述代碼僅僅找到了堆外內存分配的地方，堆外內存沒有釋放仍然有以下幾種可能：
- 程序bug導致複雜查詢未下發，從而執行鏈被丟棄而沒有回收buffer
- 程序下發了，由於未知bug導致沒有釋放buffer
dble 中複雜查詢的下發和執行都是異步調用並且邏輯鏈比較複雜，因此很難通過review代碼的方式確認是哪種情況導致。
那如何進一步縮小範圍呢？
堆內存dump
既然堆外內存泄露的比較快，平常狀態下的dump 文件中應該可以找到異常的沒有被回收的OutputHandler實例。
在dble 複雜查詢的執行鏈中，OutputHandler 實例的生命週期往往伴隨着BaseSelectHandler，因此是否可以通過異常OutputHandler的BaseSelectHandler來確定複雜查詢有沒有下發來進一步縮小範圍。
通過現場收集到的異常OutputHandler中buffer的狀態是：
正常寫出的OutputHandler中buffer的狀態是：
找到的異常的OutputHandler的BaseSelectHandler中狀態值：
可以看出其中的狀態值都是初始值，可以認為，異常的OutputHandler執行鏈沒有被執行就被丟棄了。
這樣範圍被進一步縮小，此次堆外內存泄露是由於程序bug導致複雜查詢的執行鏈被丟棄而導致的。
重新回到代碼中，review 下發複雜查詢之前和構造之後的代碼：
// com/actiontech/dble/backend/mysql/nio/handler/builder/HandlerBuilder.java
public RouteResultsetNode build(boolean isHaveHintPlan2Inner) throws Exception {
TraceManager.TraceObject traceObject = TraceManager.serviceTrace(session.getShardingService(), "build&execute-complex-sql");
try {
final long startTime = System.nanoTime();
BaseHandlerBuilder builder = getBuilder(session, node, false);
DMLResponseHandler endHandler = builder.getEndHandler();
// 泄露點在這，dble 會創建 OutputHandler，OutputHandler會分配堆外內存
DMLResponseHandler fh = FinalHandlerFactory.createFinalHandler(session);
endHandler.setNextHandler(fh);
...
RouteResultsetNode routeSingleNode = getTryRouteSingleNode(builder, isHaveHintPlan2Inner);
if (routeSingleNode != null)
return routeSingleNode;
// 下發複雜查詢，review 之前的代碼
HandlerBuilder.startHandler(fh);
session.endComplexExecute();
long endTime = System.nanoTime();
LOGGER.debug("HandlerBuilder.build cost:" + (endTime - startTime));
session.setTraceBuilder(builder);
} finally {
TraceManager.finishSpan(session.getShardingService(), traceObject);
}
return null;
}review 到 startHandler 的時候，上一個語句 return routeSingleNode 引起了我的注意。
按照邏輯，豈不是如果符合條件 routeSingleNode != null ，就不會執行 startHandler，而直接返回了。而且執行鏈的作用域在本方法內，不存在方法外的回收操作，這不就滿足了未下發而直接返回的條件了。
至此，泄露的原因找到了。
修復
修復的話，在OutputHandler中，不採取預分配buffer，而是使用到的時候才會進行分配。
總結
到這裏，整個堆外內存泄露的排查就結束了。希望對大家有幫助。
