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

Rocketmq 发送消息超时踩坑，消费正常

article 2024/10/19 9:02:54

背景

某个工作日，突然收到了生产耗时的监控报警。
日志表现如下，发送消息大量的超时日志
sendInternalImpl exception\ncom.alibaba.rocketmq.remoting.exception.RemotingTimeoutException: wait response on the channel <xx.xx.xx.xx:10911> timeout, 3000(ms) at com.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract.invokeSyncImpl(NettyRemotingAbstract.java:371) at com.alibaba.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:615) at com.alibaba.rocketmq.client.impl.MQClientAPIImpl.sendMessageSync(MQClientAPIImpl.java:398) at com.alibaba.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:385) at com.alibaba.rocketmq.client.impl.producer.DefaultMQProducerImpl.doSendKernelImpl(DefaultMQProducerImpl.java:736) at com.alibaba.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendKernelImpl(DefaultMQProducerImpl.java:661) at com.alibaba.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendInternalImpl(DefaultMQProducerImpl.java:522) at com.alibaba.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendInternalImpl(DefaultMQProducerImpl.java:489) at com.alibaba.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendDefaultImpl(DefaultMQProducerImpl.java:469) at com.alibaba.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:113) at com.alibaba.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:450) at com.alibaba.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:441)
超时异常

止损

几个业务都在反馈发送消息有超时，立马对该 broker 进行擦写，客户端更新路由信息后，该 broker 就不会再有发送消息的请求过来了。
擦写是对路由信息做了修改。

分析问题

由于消费又是正常的，排除了网络问题
夜莺里面机器的指标观察下来，问题发生的时间点没有明显的波动
捞了一遍 broker 的日志，没有发现有什么特殊的异常、错误相关的线索
决定写个测试程序，往异常 broker 上发消息，来复现这个场景。（刚才提到擦写了，所以测试程序会绕过做了修改的路由信息那块，直接发往指定的 broker 上的指定 queue）

定位问题

1、通过测试程序往该 broker 发消息，发现也是超时异常。
2、arthas 对方法进行监控，发现请求没进这个方法。
monitor com.alibaba.rocketmq.broker.processor.SendMessageProcessor processRequest -n 10 --cycle 10
3、tcpdump 抓包，确认消息是正常发送出去了
发送请求
4. arthas 监听顶层方法，发现请求过来了。
monitor com.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract processRequestCommand -n 10 --cycle 10
5. 分析该方法，捞了异常日志是没有的，排除这里出现异常的场景
在这里插入图片描述
6. 那应该就是处理器的线程有什么问题，找到发送消息处理器的线程池SendMessageThread_
this.remotingServer.registerProcessor(RequestCode.SEND_MESSAGE_V2, sendProcessor, this.sendMessageExecutor);

this.sendMessageExecutor = new ThreadPoolExecutor(// this.brokerConfig.getSendMessageThreadPoolNums(),// this.brokerConfig.getSendMessageThreadPoolNums(),// 1000 * 60,// TimeUnit.MILLISECONDS,// this.sendThreadPoolQueue,// new ThreadFactoryImpl("SendMessageThread_"));

jstack 看了 SendMessageThread_ 线程情况，发现问题了，一直处于 waiting 状态，发现是队列满了，这里的队列是 logback 里的追加日志的 queue
为啥这个 queue 会满，不是一直会取出去输出日志吗？这里应该是遇到了线程中断的异常，然后这个 sendHook 日志的处理线程退出了。队列就满了，处理发送消息的线程一直阻塞在记录 sendHook 日志的地方，所以发送消息的请求过来都无法处理，就超时了。
至于这个 sendHook 的 worker 线程为什么退出了，没有相关的日志输出，暂时看不出来。