线上问题描述
- 一周 消息发送失败差不多2400条左右
- error内容
[TIMEOUT_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: 200ms, size of queue: 9
- 线上日志
Rocketmq发送流程
可以看出来，抛出这种错误，在 broker 还没有发送“严重”的 pagecache 繁忙，即消息追加到内存中的最大时延没有超过 1s，通常追加是很快的，绝大部分都会低于1ms，但可能会由于出现一个超过200ms的追加时间，导致排队中的任务等待时间超过了200ms，则此时会触发broker 端的快速失败，让请求快速失败，便于客户端快速重试。但是这种请求并不是实时的，而是每隔10s 检查一遍
值得注意的是，一旦出现 TIMEOUT_CLEAN_QUEUE，可能在一个点会有多个这样的错误信息，具体多少与当前积压在待发送队列中的个数有关。
报错定位
-
cleanExpiredRequestInQueue会处理发送消息、拉取消息、心跳、事务消息队列中的数据，此次遇到的问题是发送Topic消息报出来的错误，所以接下来针对发送消息流程进行分析。
-
报出此错误的源码位置为broker快速失败机制BrokerFastFailure.java类(该类在Broker启动时会启动一个定时任务，每10毫秒执行一次)，报错位置代码如下：
void cleanExpiredRequestInQueue(final BlockingQueue<Runnable> blockingQueue, final long maxWaitTimeMillsInQueue) {
while (true) {
try {
if (!blockingQueue.isEmpty()) {
// 获取队列头元素
final Runnable runnable = blockingQueue.peek();
if (null == runnable) {
break;
}
final RequestTask rt = castRunnable(runnable);
if (rt == null || rt.isStopRun()) {
break;
}
final long behind = System.currentTimeMillis() - rt.getCreateTimestamp();
// 如果头元素对应的任务处理时间超过设置的最大等待时间，则处理请求返回该错误，并移除掉该任务
if (behind >= maxWaitTimeMillsInQueue) {
if (blockingQueue.remove(runnable)) {
rt.setStopRun(true);
rt.returnResponse(RemotingSysResponseCode.SYSTEM_BUSY, String.format("[TIMEOUT_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: %sms, size of queue: %d", behind, blockingQueue.size()));
}
} else {
break;
}
} else {
break;
}
} catch (Throwable ignored) {
}
}
}
这段代码是Broker快速失败机制的核心代码，如果一个等待队列的头元素(也就是第一个要处理或者正在处理的元素)等待时间超过该队列设置的最大等待时间，则丢弃该元素对象的任务，并对这个请求返回[TIMEOUT_CLEAN_QUEUE]broker busy异常信息。
发送Topic消息报该错误
sendThreadPoolQueue取出头元素，转换成对应的任务，判断任务在队列存活时间是否超过了队列设置的最大等待时间，如果超过了则组装处理返回对象response，response的code为RemotingSysResponseCode.SYSTEM_BUSY，内容为：
[TIMEOUT_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: [当前任务在队列存活时间], size of queue: [当前队列的长度]
复制代码
MQClientAPIImpl.processSendResponse处理返回response，根据response.getCode()的处理分支，最终返回MQBrokerException异常，response分支处理代码如下：
// 只有ResponseCode.SUCCESS的情况下返回结果，其他情况抛出MQBrokerException异常
private SendResult processSendResponse(
final String brokerName,
final Message msg,
final RemotingCommand response
) throws MQBrokerException, RemotingCommandException {
switch (response.getCode()) {
case ResponseCode.FLUSH_DISK_TIMEOUT:
case ResponseCode.FLUSH_SLAVE_TIMEOUT:
case ResponseCode.SLAVE_NOT_AVAILABLE: {
}
case ResponseCode.SUCCESS: {
// 省略部分代码
return sendResult;
}
default:
break;
}
throw new MQBrokerException(response.getCode(), response.getRemark());
}
消息发送客户端接收到MQBrokerException异常信息，捕获异常处理中不符合消息重试逻辑，直接抛出该异常，也就是用户看到的； // timesTotal为消息生产者设置的发送失败重试次数
for (; times < timesTotal; times++) {
String lastBrokerName = null == mq ? null : mq.getBrokerName();
MessageQueue mqSelected = this.selectOneMessageQueue(topicPublishInfo, lastBrokerName);
if (mqSelected != null) {
mq = mqSelected;
brokersSent[times] = mq.getBrokerName();
try {
// 省略部分代码
} catch (RemotingException e) {
endTimestamp = System.currentTimeMillis();
this.updateFaultItem(mq.getBrokerName(), endTimestamp - beginTimestampPrev, true);
log.warn(String.format("sendKernelImpl exception, resend at once, InvokeID: %s, RT: %sms, Broker: %s", invokeID, endTimestamp - beginTimestampPrev, mq), e);
log.warn(msg.toString());
exception = e;
continue;
} catch (MQClientException e) {
endTimestamp = System.currentTimeMillis();
this.updateFaultItem(mq.getBrokerName(), endTimestamp - beginTimestampPrev, true);
log.warn(String.format("sendKernelImpl exception, resend at once, InvokeID: %s, RT: %sms, Broker: %s", invokeID, endTimestamp - beginTimestampPrev, mq), e);
log.warn(msg.toString());
exception = e;
continue;
} catch (MQBrokerException e) {
// 此处为MQBrokerException异常处理逻辑，RemotingSysResponseCode.SYSTEM_BUSY不符合分支条件，最终throw e抛出异常
endTimestamp = System.currentTimeMillis();
this.updateFaultItem(mq.getBrokerName(), endTimestamp - beginTimestampPrev, true);
log.warn(String.format("sendKernelImpl exception, resend at once, InvokeID: %s, RT: %sms, Broker: %s", invokeID, endTimestamp - beginTimestampPrev, mq), e);
log.warn(msg.toString());
exception = e;
switch (e.getResponseCode()) {
case ResponseCode.TOPIC_NOT_EXIST:
case ResponseCode.SERVICE_NOT_AVAILABLE:
case ResponseCode.SYSTEM_ERROR:
case ResponseCode.NO_PERMISSION:
case ResponseCode.NO_BUYER_ID:
case ResponseCode.NOT_IN_CURRENT_UNIT:
continue;
default:
if (sendResult != null) {
return sendResult;
}
throw e;
}
} catch (InterruptedException e) {
endTimestamp = System.currentTimeMillis();
this.updateFaultItem(mq.getBrokerName(), endTimestamp - beginTimestampPrev, false);
log.warn(String.format("sendKernelImpl exception, throw exception, InvokeID: %s, RT: %sms, Broker: %s", invokeID, endTimestamp - beginTimestampPrev, mq), e);
log.warn(msg.toString());
log.warn("sendKernelImpl exception", e);
log.warn(msg.toString());
throw e;
}
} else {
break;
}
}
解决方案
- 业务逻辑处理中进行异常捕获，如果捕获到异常为MQBrokerException并且responseCode匹配则重发消息；
- 修改broker的默认发送消息任务队列等待时长waitTimeMillsInSendQueue(单位: 毫秒)；
