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

头像
爱可生云数据库
    3551
    发布于
    上海
     

    作者：鲍凤其

    爱可生 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内存泄露
    本作品系原创，采用《署名-非商业性使用-禁止演绎 4.0 国际》许可协议
    MySQL分布式中间件DBLE
    DBLE是一个基于MySQL的高可扩展性的分布式中间件，适用于高并发及TB级海量数据处理场景。
    avatar

    中国领先的企业数据处理技术整体解决方案提供商，开源数据库领域优秀企业。为大型行业用户的特定场景提...

    355 声望
    178 粉丝
    0 条评论
    得票最新
    推荐阅读
    技术分享 | OceanBase 租户延迟删除
    作者：杨涛涛资深数据库专家，专研 MySQL 十余年。擅长 MySQL、PostgreSQL、MongoDB 等开源数据库相关的备份恢复、SQL 调优、监控运维、高可用架构设计等。目前任职于爱可生，为各大运营商及银行金融企业提供 MyS...

    爱可生云数据库阅读 70

    Java Nio Example
    select模型，它的基本原理是采用轮询和遍历的方式。也就是说，在客户端操作服务器时，会创建三种文件描述符，简称FD。分别是writefds（写描述符）、readfds（读描述符）和 exceptfds（异常描述符）

    Rylan阅读 792

    封面图
    JVM说--直接内存的使用
    前言： 学习底层原理有的时候不一定你是要用到他，而是学习他的设计思想和思路。再或者，当你在日常工作中遇到棘手的问题时候，可以多一条解决问题的方式

    京东云开发者赞 2阅读 314

    封面图
    一文详解 Netty 组件
    作为较底层的网络通信框架，其被广泛应用在各种中间件的开发中，比如 RPC框架、MQ、Elasticsearch等，这些中间件框架的底层网络通信模块大都利用到了 Netty 强大的网络抽象

    京东云开发者赞 2阅读 300

    封面图
    Redis 异步客户端选型及落地实践
    为了支持更加广泛的业务场景，可视化编排系统近期需要支持对缓存的操作功能，为保证编排系统的性能，服务的执行过程采用了异步的方式，因此我们考虑使用Redis的异步客户端来完成对缓存的操作。

    京东云开发者赞 1阅读 194

    封面图
    io的基本原理-nio
    操作系统将内存（虚拟内存）划分为两部分：一部分是内核空间（Kernel-Space），另一部分是用户空间（User-Space）应用程序不允许直接在内核空间区域进行读写，也不允许直接调用内核代码定义的函数。每个应用程序...

    用户bPcVmzR阅读 285

    封面图
    Tars-Java网络编程源码分析
    Tars是腾讯开源的支持多语言的高性能RPC框架，起源于腾讯内部2008年至今一直使用的统一应用框架TAF（Total Application Framework），目前支持C++、Java、PHP、Nodejs、Go语言。

    vivo互联网技术

    avatar

    中国领先的企业数据处理技术整体解决方案提供商，开源数据库领域优秀企业。为大型行业用户的特定场景提...

    355 声望
    178 粉丝
    宣传栏