当前位置：首页 > news >正文

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

news 来源：原创 2024/11/18 17:47:02

大家好：

我是烤鸭。连续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);
    }
}