线上RocketMQ偶发sendDefaultImpl call timeout问题排查及优化方向总结

背景

最近线上偶发少量报错

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

问题排查

通过相关的报错可以发现是消息发送超时了。

具体是哪里超时了还要继续深入分析

源码分析

源码版本 5.1.0

这里我们首先来看看源码大致会在哪里超时

全局搜索sendDefaultImpl call timeout，发现仅一处抛出这个异常

这里我们点进去看看具体代码

这里可以看到如果是callTimeout为true则抛出异常。

我们现在来看看何时会为true

超时时间检测主要是通过long costTime = beginTimestampPrev - beginTimestampFirst;进行判断

在这个时间段中我们看看MQ这边做了哪些耗时操作

1. 获取topic元数据信息

TopicPublishInfo topicPublishInfo = this.tryToFindTopicPublishInfo(msg.getTopic());

可以看到主要是tryToFindTopicPublishInfo进行了一些网络处理，会存在延时。

我们具体看看这里的代码

    private final ConcurrentMap<String/* topic */, TopicPublishInfo> topicPublishInfoTable =
        new ConcurrentHashMap<>();

    private TopicPublishInfo tryToFindTopicPublishInfo(final String topic) {
        TopicPublishInfo topicPublishInfo = this.topicPublishInfoTable.get(topic);
        if (null == topicPublishInfo || !topicPublishInfo.ok()) {
            this.topicPublishInfoTable.putIfAbsent(topic, new TopicPublishInfo());
            this.mQClientFactory.updateTopicRouteInfoFromNameServer(topic);
            topicPublishInfo = this.topicPublishInfoTable.get(topic);
        }

        if (topicPublishInfo.isHaveTopicRouterInfo() || topicPublishInfo.ok()) {
            return topicPublishInfo;
        } else {
            this.mQClientFactory.updateTopicRouteInfoFromNameServer(topic, true, this.defaultMQProducer);
            topicPublishInfo = this.topicPublishInfoTable.get(topic);
            return topicPublishInfo;
        }
    }

这里可以看到topicPublishInfoTable是一个全局变量，相当于一个JVM级别的内存缓存。

如果没有相关的路由信息，则通过updateTopicRouteInfoFromNameServer方法进行获取并进行缓存更新

这里可以看到一行关键代码

private final Lock lockNamesrv = new ReentrantLock();

this.lockNamesrv.tryLock(LOCK_TIMEOUT_MILLIS, TimeUnit.MILLISECONDS)

这里可以看到是使用了一个ReentrantLock

值得注意的是这里没有使用类似双重检查锁的机制

那么就会出现一个问题

比如我一个JVM进程多个线程对一个topic进行消息发送的时候。

a 线程会进行updateTopicRouteInfoFromNameServer并成功获取到lockNamesrv这把锁

b 线程也会进行updateTopicRouteInfoFromNameServer但是未获取到锁进行等待

等a线程获取完成后会进行topic路由元数据缓存。然后释放锁 b此时获取到锁并没有重新进行缓存元数据检测，还是会重复去NameServer进行网络通信获取topic元数据

此时如果网络有一定的延迟，就有可能造成a线程执行tryLock之后处于等待的其他线程出现sendDefaultImpl call timeout

毕竟client消息发送默认的超时时间还是太短了只有3s

initTopicRoute

如果我们继续深入分析源码会发现initTopicRoute这么一个方法

这个方法会在producer启动的时候就去拉去tpoic元数据信息

private void initTopicRoute() {
        List<String> topics = this.defaultMQProducer.getTopics();
        if (topics != null && topics.size() > 0) {
            topics.forEach(topic -> {
                String newTopic = NamespaceUtil.wrapNamespace(this.defaultMQProducer.getNamespace(), topic);
                TopicPublishInfo topicPublishInfo = tryToFindTopicPublishInfo(newTopic);
                if (topicPublishInfo == null || !topicPublishInfo.ok()) {
                    log.warn("No route info of this topic: " + newTopic + FAQUrl.suggestTodo(FAQUrl.NO_TOPIC_ROUTE_INFO));
                }
            });
        }
    }

我们也可以考虑使用这个方法来进行topic的元数据提前加载。 不过这不是一个根本的解决方案

而且这个方法的作用不是做这个是，是给事务消息使用的。

详细说明可以参考issues：https://github.com/apache/rocketmq/issues/7567

定时更新topic元数据信息

如果我们查看startScheduledTask这方法会发现在定时任务中也有更新元数据信息的操作

默认是3s一次

值得注意的是这里

阿里云商业sdk默认超时时间

如果我们对比开源和商业的sdk会发现阿里云商业版的sdk默认消息发送超时时间是5s

而开源版本是3s，3s显然感觉有点短，可以像阿里云设置长一点点

• 阿里云

• 开源

开源在构造的时候不会设置超时时间，默认就是3s，阿里云会在没有设置超时时间是设置超时时间为5s

sendDefaultImpl call timeout vs sendKernelImpl call timeout

值得注意的我们这里抛出的异常是sendDefaultImpl call timeout并不是sendKernelImpl call timeout

sendDefaultImpl call timeout代表的是还没进行消息发送就已经超时了

所以超时是时间应该主要是在获取topic元数据导致的

总结

首先我们可以确定的是发生sendDefaultImpl call timeout是还没有发送消息就超时了导致的。发生超时主要应该是在获取topic元数据导致的

那么导致超时的原因可能有哪些呢？

1. topic第一发送消息多个线程获取topic元数据信息同步等待锁后又重新从Nameserver获取导致的超时
2. topic第一发送消息获取topic元数据真正的网络延时导致的超时(这种情况可能比较少，因为一般RocketmQ和client都是在一个内网)
3. JVM Full GC stop the world导致的超时

值得注意的是如果是timeOut导致的消息发送异常是不会重新发送消息的

解决方案：

1. 优化获取topic元数据代码
2. 延长超时时间