作者：鮑鳳其
愛可生 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，而是使用到的時候才會進行分配。
總結
到這裡，整個堆外記憶體洩露的排查就結束了。希望對大家有幫助。