rocketmq报错的问题排查和记录 RemotingTooMuchRequestException

阿里云国内75折回扣微信号：monov8

阿里云国际，腾讯云国际，低至75折。AWS 93折免费开户实名账号代冲值优惠多多微信号：monov8 飞机：@monov6

大家好

我是烤鸭。连续3天同一时间遇到rocketmq不可用。第一天持续1分钟第二天持续10分钟第三天持续40分钟。线上版本使用的4.9.2以下源码均看的这个版本。

问题描述

12:00 左右服务大量报错报错日志主要是

org.apache.rocketmq.remoting.exception.RemotingTooMuchRequestException: sendDefaultImpl call timeout

偶尔有几条

org.apache.rocketmq.client.exception.MQBrokerException: CODE: 2  DESC: [PCBUSY_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: 1481ms, size of queue: 33

org.apache.rocketmq.client.exception.MQClientException: No route info of this topic:xxxx

日志分析&原因猜想

排除网络和业务服务问题

首先我们要排除网络原因或者我们本地服务配置的问题。

流量没有增长rocketmq的整体QPS也很低不可能是网上说的几万QPS导致服务刷盘慢导致的。

第一天出问题的时候就让运维把rocketmq的日志拉下来看了由于rocketmq集群是用容器刚搭的很多监控都没有。

日志断点认定broker问题

只能通过日志猜发现broker是在短时间内停摆。

watermark.log中的日志正常应该每秒连续输出的现在出现了断点。

2023-01-11 12:00:01 - [WATERMARK] Pull Queue Size: 0 SlowTimeMills: 0
2023-01-11 12:00:01 - [WATERMARK] Query Queue Size: 0 SlowTimeMills: 0
2023-01-11 12:00:01 - [WATERMARK] Transaction Queue Size: 0 SlowTimeMills: 0
2023-01-11 12:00:12 - [WATERMARK] Send Queue Size: 0 SlowTimeMills: 0
2023-01-11 12:00:12 - [WATERMARK] Pull Queue Size: 0 SlowTimeMills: 0
2023-01-11 12:00:12 - [WATERMARK] Query Queue Size: 0 SlowTimeMills: 0

再根据 PCBUSY_CLEAN_QUEUE 看下 DefaultMessageStore.java 源码

osPageCacheBusyTimeOutMills = 8000

这个配置是刷盘的超时时间默认1s我们配置的是8s。记录的上一次commitlog的刷盘时间每10ms检查1次如果间隔时间超过设置这个值的话isOSPageCacheBusy 的时候才会抛出这个异常。

private void cleanExpiredRequest() {
    while (this.brokerController.getMessageStore().isOSPageCacheBusy()) {
        try {
            if (!this.brokerController.getSendThreadPoolQueue().isEmpty()) {
                final Runnable runnable = this.brokerController.getSendThreadPoolQueue().poll(0, TimeUnit.SECONDS);
                if (null == runnable) {
                    break;
                }

                final RequestTask rt = castRunnable(runnable);
                rt.returnResponse(RemotingSysResponseCode.SYSTEM_BUSY, String.format("[PCBUSY_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: %sms, size of queue: %d", System.currentTimeMillis() - rt.getCreateTimestamp(), this.brokerController.getSendThreadPoolQueue().size()));
            } else {
                break;
            }
        } catch (Throwable ignored) {
        }
    }

也猜想过是不是服务器时间变动导致的不过立刻被否定了因为持续了数分钟中间断断续续不是一瞬间的事。

如果服务器时间同步后拨那应该只报一段时间。而且服务器的时间有监控并没发现问题。

罪魁祸首

12点肯定执行了什么触发了broker的宕机而且发生了主从切换。不过第三天主从切换后仍然不可用持续近1小时才恢复。

看日志发现 DLedgerCleanSpaceService 这个线程执行Flush data cost 耗时特别长。

2023-01-11 12:00:00 INFO DLedgerCleanSpaceService - unmap file[REF:0] /home/rocketmq/store/dledger-n2/data/xxxxxxxxxxxx OK
2023-01-11 12:00:00 INFO DLedgerCleanSpaceService - close file channel /home/rocketmq/store/dledger-n2/data/xxxxxxxxxxxxx OK
...省略部分日志,主从节点传输不同
INFO DLedgerFlushDataService - Flush data cost=12341 ms

我们看下这个配置不配置默认的也是04这个是删除之前的 commitlog的时间设置本来设置的4点不过容器时区问题现在变成12点执行了。

deleteWhen=04

源码 DLedgerMmapFileStore.java

两个flush耗时巨长。

@Override public void doWork() {
    try {
        long start = System.currentTimeMillis();
        DLedgerMmapFileStore.this.dataFileList.flush(0);
        DLedgerMmapFileStore.this.indexFileList.flush(0);
        if (DLedgerUtils.elapsed(start) > 500) {
            logger.info("Flush data cost={} ms", DLedgerUtils.elapsed(start));
        }

        if (DLedgerUtils.elapsed(lastCheckPointTimeMs) > dLedgerConfig.getCheckPointInterval()) {
            persistCheckPoint();
            lastCheckPointTimeMs = System.currentTimeMillis();
        }

        waitForRunning(dLedgerConfig.getFlushFileInterval());
    } catch (Throwable t) {
        logger.info("Error in {}", getName(), t);
        DLedgerUtils.sleep(200);
    }
}