关于nio:分布式-令人头疼的堆外内存泄露怎么排查

42次阅读

共计 7483 个字符，预计需要花费 19 分钟才能阅读完成。

作者：鲍凤其

爱可生 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;
}

review 到 startHandler 的时候，上一个语句 return routeSingleNode 引起了我的留神。

依照逻辑，岂不是如果符合条件 routeSingleNode != null，就不会执行 startHandler，而间接返回了。而且执行链的作用域在本办法内，不存在办法外的回收操作，这不就满足了未下发而间接返回的条件了。

至此，泄露的起因找到了。

修复

修复的话，在 OutputHandler 中，不采取预调配 buffer，而是应用到的时候才会进行调配。

总结

到这里，整个堆外内存泄露的排查就完结了。心愿对大家有帮忙。

正文完
nio
发表至： nio
2022-12-15
 0
关于nio:IO零拷贝
关于nio:linuxbio与nio的区别
关于nio:Java-NIO-基础四-选择器
关于nio:线程安全