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

  大家好：

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

实景复盘

第一天出事的时候，查了一天，监控没有，也不太好定位问题，还以为官方有什么bug，而且只持续了1分钟，有点掉以轻心了。

等到第二天出事的时候，运维反馈发现网上类似情况，把配置修改完重启了，理论上增加了删除次数，应该不会报错了。

deleteWhen=01;04;07;10;13;17;19;22

第三天出事的时候，傻眼了，也终于找到问题了。

因为这时候来找运维的人不止我们一个部门，所有部署在容器的rocketmq集群都受影响了，这些集群共通点就是挂载的同一个外挂硬盘。再加上配置都是一样的，不一定哪个集群12点删除日志的时候把磁盘性能打满了，影响了其他集群。

这里还有一个问题：

本来容器集群就是新上的，使用的人并不多，QPS肯定不高，commitlog也不多。

就算同时触发删除，也不至于影响broker几十分钟。

运维给的解释是外挂磁盘的性能实在是太差了，500M文件删起来都费劲，离谱。

解决方案

因为之前部署的rocketmq集群都是用虚机部署的，本地的磁盘环境又都是相互隔离的，删除个几十G文件性能还是能保证的。

• 升级磁盘（既然知道磁盘性能，直接硬件先解决，不过没有解决隔离性问题）
• 更换虚机集群（问题都能解决，就是业务端需要重启，还要考虑服务丢失问题）
• 更换容器集群，分离集群挂载目录，升级磁盘（同上）

总结

这次的问题就是容器外挂磁盘的性能问题导致，其次还有多个集群共用一个磁盘目录也是问题。

公司新推出的组件不要着急尝试，之前推出的apisix网关也是，不少人反馈接入之后有问题。

除非有KPI要求，其他还是稳定为主。尤其是新搞的这种，连监控都不全的，真的太危险了。

一出问题，运维就说就是没有错误日志，是不是网络问题或者服务配置问题。

太盲目扩张也不好，还是稳扎稳打做基建更重要。

参考文章

https://www.cnblogs.com/dingwpmz/p/12104702.html

滴滴出行基于RocketMQ构建企业级消息队列服务的实践_架构_江海挺_InfoQ精选文章

https://www.luckycxy.com/articles/2018/05/13/1643729483089.html