broker 返回异常 [TIMEOUT_CLEAN_QUEUE]broker busy

[LinkCaau]

看了很久没看出来哪里有问题, 也定位不了究竟是哪个Runnable超时了.
只知道是 BrokerController$sendMessageExecutor 的task超时了

broker返回异常

org.apache.rocketmq.client.exception.MQBrokerException: CODE: 2 DESC: [TIMEOUT_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: 1322ms, size of queue: 0 BROKER: 10.2.0.4:10911

栈信息

tid.txt

[cserwen]

这里是是服务端 Broker 因为 busy 而快速失败返回给客户端的，具体方法你可以看下 cleanExpiredRequestInQueue，如果队头任务等待时间超过了配置值（默认为200ms）就会 fast fail，以便客户端快速到其他节点重试

一般常见于发送队列，对于发送，最可能的就是 操作系统 pagecache 进行同步回收，阻塞了写入，然后导致写入队列堆积，可以看下服务端 store.log 中有没有以下日志来判断

[NOTIFYME]putMessage in lock cost time(ms)={}, bodyLength={} AppendMessageResult={}

[LinkCaau]

没有打印这个日志
这是store.log 2024-05-22 13:19的日志

2024-05-22 13:19:00 INFO AdminBrokerThread_4 - findPutMessageEntireTimePX 0.99=0.00ms cost 0ms
2024-05-22 13:19:00 INFO AdminBrokerThread_4 - findPutMessageEntireTimePX 0.999=0.00ms cost 0ms
2024-05-22 13:19:01 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:01.61] num:20 cost:10005 tps:2.0090 min:0 max:99999999 tp50:0 tp80:0 tp90:0 tp99:0 tp999:0 0_1:20 2_5:0 6_10:0 11_50:0 51_100:0 101_500:0 501_999:0 1000_:0
2024-05-22 13:19:07 INFO TimerFlushService - [SYNC_MASTER]Timer progress-check commitRead:[05-22 05:19:07] currRead:[05-22 05:19:07] currWrite:[05-22 05:19:07] readBehind:0 currReadOffset:0 offsetBehind:0 behindMaster:0 enqPutQueue:0 deqGetQueue:0 deqPutQueue:0 allCongestNum:0 enqExpiredStoreTime:01-01 00:00:00
2024-05-22 13:19:11 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:11.615] num:20 cost:10005 tps:2.0090 min:0 max:99999999 tp50:0 tp80:0 tp90:0 tp99:0 tp999:0 0_1:20 2_5:0 6_10:0 11_50:0 51_100:0 101_500:0 501_999:0 1000_:0
2024-05-22 13:19:12 INFO StoreStatsService - [STORETPS] put_tps 0.0 get_found_tps 0.0 get_miss_tps 43.239190202449386 get_transferred_tps 0.0
2024-05-22 13:19:12 INFO StoreStatsService - findPutMessageEntireTimePX 0.99=0.00ms cost 0ms
2024-05-22 13:19:12 INFO StoreStatsService - findPutMessageEntireTimePX 0.999=0.00ms cost 0ms
2024-05-22 13:19:12 INFO StoreStatsService - [PAGECACHERT] TotalPut 0, PutMessageDistributeTime [<=0ms]:0 [010ms]:0 [1050ms]:0 [50100ms]:0 [100200ms]:0 [200500ms]:0 [500ms1s]:0 [12s]:0 [23s]:0 [34s]:0 [45s]:0 [510s]:0 [10s]:0
2024-05-22 13:19:17 INFO TimerFlushService - [SYNC_MASTER]Timer progress-check commitRead:[05-22 05:19:17] currRead:[05-22 05:19:17] currWrite:[05-22 05:19:17] readBehind:0 currReadOffset:0 offsetBehind:0 behindMaster:0 enqPutQueue:0 deqGetQueue:0 deqPutQueue:0 allCongestNum:0 enqExpiredStoreTime:01-01 00:00:00
2024-05-22 13:19:21 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:21.62] num:20 cost:10005 tps:2.0090 min:0 max:99999999 tp50:0 tp80:0 tp90:0 tp99:0 tp999:0 0_1:20 2_5:0 6_10:0 11_50:0 51_100:0 101_500:0 501_999:0 1000_:0
2024-05-22 13:19:26 INFO compactionSchedule_1 - start to scan all topicConfig
2024-05-22 13:19:26 INFO compactionSchedule_1 - scan all topicConfig over
2024-05-22 13:19:28 INFO TimerFlushService - [SYNC_MASTER]Timer progress-check commitRead:[05-22 05:19:28] currRead:[05-22 05:19:28] currWrite:[05-22 05:19:28] readBehind:0 currReadOffset:0 offsetBehind:0 behindMaster:0 enqPutQueue:0 deqGetQueue:0 deqPutQueue:0 allCongestNum:0 enqExpiredStoreTime:01-01 00:00:00
2024-05-22 13:19:31 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:31.625] num:20 cost:10005 tps:2.0090 min:0 max:99999999 tp50:0 tp80:0 tp90:0 tp99:0 tp999:0 0_1:20 2_5:0 6_10:0 11_50:0 51_100:0 101_500:0 501_999:0 1000_:0
2024-05-22 13:19:41 INFO TimerFlushService - [SYNC_MASTER]Timer progress-check commitRead:[05-22 05:19:39] currRead:[05-22 05:19:39] currWrite:[05-22 05:19:39] readBehind:0 currReadOffset:0 offsetBehind:0 behindMaster:0 enqPutQueue:0 deqGetQueue:0 deqPutQueue:0 allCongestNum:0 enqExpiredStoreTime:01-01 00:00:00
2024-05-22 13:19:42 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:42.067] num:18 cost:10442 tps:1.7334 min:0 max:308 tp50:0 tp80:0 tp90:0 tp99:308 tp999:308 0_1:17 2_5:0 6_10:0 11_50:0 51_100:0 101_500:1 501_999:0 1000_:0
2024-05-22 13:19:50 INFO TimerFlushService - [SYNC_MASTER]Timer progress-check commitRead:[05-22 05:19:50] currRead:[05-22 05:19:50] currWrite:[05-22 05:19:50] readBehind:0 currReadOffset:0 offsetBehind:0 behindMaster:0 enqPutQueue:0 deqGetQueue:0 deqPutQueue:0 allCongestNum:0 enqExpiredStoreTime:01-01 00:00:00
2024-05-22 13:19:52 INFO FlushRealTimeService - PERF_COUNTER_FLUSH_DATA_TIME_MS[2024-05-22 05:19:52.084] num:20 cost:10017 tps:2.0066 min:0 max:13 tp50:0 tp80:0 tp90:0 tp99:13 tp999:13 0_1:19 2_5:0 6_10:0 11_50:1 51_100:0 101_500:0 501_999:0 1000_:0
2024-05-22 13:19:56 INFO compactionSchedule_1 - start to scan all topicConfig
2024-05-22 13:19:56 INFO compactionSchedule_1 - scan all topicConfig over