分布式 | 令人头疼的堆外内存泄露怎么排查？

爱可生开源社区 2022-12-13

528

作者：鲍凤其

爱可生 dble 团队开发成员，主要负责 dble 需求开发，故障排查和社区问题解答。少说废话，放码过来。

本文来源：原创投稿

*爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

大家在使用 Java NIO 的过程中，是不是也遇到过堆外内存泄露的问题？是不是也苦恼过如何排查？

下面就给大家介绍一个在 dble 中排查堆外内存泄露的案例。

现象

有客户在使用 dble 之后，有一天 dble 对后端 MySQL 实例的心跳检测全部超时，导致业务中断，最后通过重启解决。

分析过程

dble 日志

首先当然是分析 dble 日志。从 dble 日志中可以发现：

1. 故障时间点所有后端 MySQL 实例心跳都超时

2. 日志中出现大量“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

通过上面的日志猜测：

1. 所有 MySQL 实例超时是很特殊的，可能是由于故障时间发生了长时间停顿的gc

2. 而长时间停顿的 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();
}

通过上面的代码可以判断在构造复杂查询执行链的时候会分配堆外内存。

问题到这其实还是没有解决，上述代码仅仅找到了堆外内存分配的地方，堆外内存没有释放仍然有以下几种可能：

1. 程序bug导致复杂查询未下发，从而执行链被丢弃而没有回收 buffer

2. 程序下发了，由于未知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;
}