叙事框架现象 → 排查过程 → 根因 → 修复 → 预防问题现象RocketMQ 消息发送返回 SYSTEM_BUSYCODE: 2是生产环境中常见但容易被误判的错误。本文基于一次真实的生产故障从应用日志 → Broker 日志 → 系统指标 → mqadmin 运行时状态 → jstack 线程栈 → 源码分析完整还原排查过程。某日早高峰支付服务上线状态同步功能后出现大量 MQBrokerException: CODE: 2 DESC: [TIMEOUT_CLEAN_QUEUE]broker busy。错误特征为队列等待时间从 506ms 持续增长至 1892ms队列积压从 957 涨至 3567。排查发现 Broker 端 sendMessageThreadPoolNums 为默认值 1且 CommitLog.putMessage 的 ReentrantLock 在磁盘 IO 压力下持有时间从微秒级膨胀到数百毫秒。最终定位为三层瓶颈叠加线程池过小 写锁竞争 磁盘 IO。排查过程第一步Broker 端日志确认上到 RocketMQ Broker 机器先看 broker 日志日志清晰地记录了SendMessageThread_1反复输出wait too long in send queue xxx abort。每个请求在队列里排队等待的时间持续增长从 506ms 涨到 1892ms队列积压从 957 涨到 3567。这说明 Broker 端的发送线程池已经严重过载——请求进来后无法被及时处理在队列里排队超时后被 BrokerFastFailure 机制主动拒绝。第二步系统资源排查首先用top看系统整体状态CPU 才 35% 使用率52% 空闲——说明系统瓶颈不在 CPU。但 load average 高达 42而且是持续攀升趋势。这里有一个关键判断CPU 空闲 load 高 进程在等 IO不可中断睡眠态。再看 RocketMQ Java 进程信息CPU 156%多线程累加、RES 8.7G、S 状态列是Ssleeping。进程占用了 8.7G 内存其中大部分是 PageCache——这正是 RocketMQ 利用 mmap 写入 CommitLog 的内存映射区域。用vmstat进一步确认 IO 状况重点关注三列b不可中断睡眠进程数从 0 爬到 4说明确实有线程在等 IO 完成bi块设备读入从 412 KB/s 涨到 2467 KB/s——磁盘读取在持续增加waIO wait CPU从 1% 涨到 8%CPU 等待 IO 的比例在上升同时注意到free空闲内存在持续下降从 2137MB → 1923MB而cache在增长28852 → 28859MB。这符合 PageCache 增长的预期——RocketMQ 写入 CommitLog 时通过 mmap 映射文件大量写入会导致 PageCache 占用上涨进而挤压空闲内存。第三步磁盘 IO 定位瓶颈用iostat -x定位磁盘级别的问题数据盘sdc的%util达到 98.6%~99.1%基本满负荷运转。这里逐一解读关键指标r/s 312, w/s 1623每秒 312 次读 1623 次写主要是 RocketMQ 的异步刷盘和 ReputMessageService 构建 ConsumeQueue 读操作rkB/s ≈ 12.8MB, wkB/s ≈ 128.9MB写入带宽约 129MB/s对于机械盘或入门级 SSD 都不是小数字avgqu-sz 12.45磁盘请求队列深度超过 12说明有大量 IO 请求在排队等待处理await 12.34msIO 请求从提交到完成平均等待 12ms正常 SSD 应该在 12ms机械盘在 58msw_await 13.21ms写请求的响应时间更长写操作在等待刷盘svctm 0.51msIO 请求的实际服务时间很短0.5ms说明磁盘本身硬件没有问题问题是请求太多排起了长队svctm和await的差距0.51ms vs 12.34ms是判断 IO 瓶颈的关键信号——硬件处理速度是够的但请求数量远超硬件处理能力导致大量排队。sdc正是 RocketMQ 的存储盘CommitLog、ConsumeQueue 都在这块盘上。高 IO 负载导致每次putMessage写入 CommitLog 的时间变长。第四步Broker 运行时指标使用mqadmin getBrokerRuntime查看 Broker 内部运行状况关键信息是putMessageDistributeTime——消息追加到 CommitLog 的耗时分布耗时区间次数占比≤50ms00%50~100ms8566.8%100~200ms324525.6%200~500ms567844.9%500~1000ms234118.5%1s5364.2%44.9% 的消息追加耗时在 200~500ms 之间这是不可接受的。正常情况下 RocketMQ 的 putMessage 内部操作包括获取 putMessageLock → 追加消息到 MappedFile → 更新逻辑队列 → 释放锁。这些操作全是内存级操作应该在 1ms 以内完成。200~500ms 说明锁竞争严重或者 MappedFile 的内存映射写入被 PageCache 回写阻塞了。其他值得注意的指标putMessageTimesTotal: 12656Broker 启动以来总共处理了 12656 次 putMessage 调用dispatchBehindBytes: 234567890ReputMessageService 构建 ConsumeQueue 的进度落后了 234MB——消息写入 CommitLog 后后台构建 ConsumeQueue 的线程跟不上写入了pageCacheWriteLive: falsePageCache 写入没有启用流控sendMessageThreadPoolNums: 1这个等下重点分析dispatchBehindBytes非零是一个危险信号——如果 ConsumeQueue 构建跟不上 CommitLog 写入消费者可能读不到最新消息进一步放大问题。第五步Broker 配置检查查看 Broker 的关键配置发现了第一个关键问题——sendMessageThreadPoolNums 1。这个参数控制 Broker 处理消息发送请求的线程池大小。默认值为 1意味着所有生产者的发送请求都由同一个线程串行处理。其他配置如waitTimeMillsInSendQueue200、osPageCacheBusyEnablefalse也都偏保守。第六步线程栈深度分析为了搞清楚那唯一一个 SendMessageThread 到底在等什么抓了 jstackSendMessageThread_1在CommitLog.putMessage()处获取ReentrantLock时被阻塞处于 RUNNABLE 状态但实际在 park 等待锁。SendMessageThread_2则在更后面排队等同一个锁。这意味着sendMessageThreadPoolNums1限制了只能有一个线程处理请求这个唯一线程在CommitLog.putMessage上抢锁锁释放慢因为磁盘 IO 高写入 CommitLog 的 MappedFile 耗时增加后续请求在队列中越等越久触发BrokerFastFailure拒绝第七步源码定位看一下 RocketMQ Broker 处理发送请求的核心源码SendMessageProcessor.asyncProcessRequest()将请求提交到sendMessageExecutor线程池该线程池的大小就是sendMessageThreadPoolNums默认 1。CommitLog.putMessage()内部使用ReentrantLock来保护 MappedFile 的追加写入。虽然 RocketMQ 4.x 后期版本支持了putMessageLock类型配置可以选择自旋锁或 ReentrantLock但锁的粒度是 CommitLog 级别的——同一时刻只能有一个线程写入。再看客户端发送代码客户端使用的是同步发送producer.send(msg)没有设置超时、没有重试机制、没有降级策略。一旦 Broker 返回 SYSTEM_BUSY直接抛出异常导致业务失败。根因分析本问题的根因是三层瓶颈叠加。单独任何一层都不会导致 SYSTEM_BUSY但三层同时发作就形成了完美的负面放大效应。第一层发送线程池瓶颈直接原因sendMessageThreadPoolNums1是 RocketMQ 4.x 的系统默认值。这个参数控制的是BrokerController中sendMessageExecutor线程池的核心线程数。所有生产者发送的消息Netty 接收到后解码成RemotingCommand然后提交到这个线程池执行。线程池使用LinkedBlockingQueue作为工作队列容量为Integer.MAX_VALUE无界队列。但这并不意味着队列永远不会满——BrokerFastFailure机制会每隔brokerFastFailureInterval默认 10ms扫描队列头部的请求如果某个请求在队列中的等待时间超过了waitTimeMillsInSendQueue默认 200ms就会直接拒绝该请求并返回 SYSTEM_BUSY而不是让它继续排队等待。当消息量从 2000 TPS 涨到 8000 TPS单线程处理能力遇到上限每个消息的 putMessage 耗时因磁盘 IO 压力增加到 200~500ms单个线程每秒最多处理 2~5 个消息8000 TPS 的需求与 5 TPS 的处理能力形成巨大剪刀差第二层CommitLog 写锁竞争架构瓶颈即使增加线程池大小CommitLog.putMessage()的ReentrantLock仍然是单点瓶颈。这里需要深入理解 RocketMQ 的存储架构RocketMQ 的消息存储采用「单一 CommitLog 异步构建队列」的模型。所有消息都顺序追加到 CommitLog 文件中。CommitLog 由一组MappedFile内存映射文件组成每个文件固定 1GB。当写满一个文件后创建下一个文件继续写。putMessage方法内部大致流程putMessageLock.lock()try{MappedFilemappedFilethis.mappedFileQueue.getLastMappedFile();AppendMessageResultresultmappedFile.appendMessage(msg);// 更新逻辑队列偏移this.logicsQueue.setMaxOffset(...);}finally{putMessageLock.unlock();}ReentrantLock 的锁持有时间取决于MappedFile.appendMessage的执行时间。在正常情况下这只是一次内存拷贝将消息字节复制到 mmap 映射的内存区域耗时在微秒级。但当 PageCache 压力大时Linux 内核的mmap写入可能会触发page fault和脏页回写导致appendMessage阻塞在 IO 上。在 RocketMQ 5.x 中引入了「Multi-Threading PutMessage」的优化通过分段锁Segment Lock将 CommitLog 的并发度提高到多个线程。但 4.x 版本的putMessageLock是全局锁并发度只能为 1。第三层磁盘 IO 瓶颈底层原因磁盘 IO 是本次问题的深层原因也是根因的根因。三个方面加剧了磁盘压力消息量从 2000 TPS 涨到 8000 TPS假设每条消息平均 2KB写入带宽从 4MB/s 涨到 16MB/sRocketMQ 的 CommitLog 写入通过 mmap 映射到 PageCacheLinux 内核的 PageCache 回写策略当脏页比例超过vm.dirty_ratio默认 20%时写入进程会被阻塞触发回写ReputMessageService异步构建 ConsumeQueue 时需要读取 CommitLog 文件这种「写后立即读」的模式在 IO 繁忙时形成读写叠加压力flushDiskTypeASYNC_FLUSH只是说 RocketMQ 的刷盘线程不主动等待数据写到磁盘——但操作系统层面PageCache 的脏页回写是自动触发的。当脏页比例上升内核会强制进行回写此时MappedFile.appendMessage中的 memcpy 操作看起来是「内存操作」实际上可能触发 page fault 等待脏页刷盘。综合触发链路消息量激增(2000→8000 TPS)↓ CommitLog 写入量增大mmap PageCache 写入 ↓ 脏页比例上升 → 内核触发 PageCache 回写 ↓ MappedFile.appendMessage 因回写阻塞微秒级 → 百毫秒级 ↓ putMessage ReentrantLock 持有时间从微秒级增加到数百毫秒 ↓ 单线程池sendMessageThreadPoolNums1处理能力不足 ↓ BrokerFastFailure 检测到队列等待200ms ↓ 拒绝请求 → 返回 SYSTEM_BUSYCODE:2给生产者修复方案针对三层瓶颈给出三层修复第一层增加发送线程池 调优等待时间sendMessageThreadPoolNums 8 waitTimeMillsInSendQueue 500 osPageCacheBusyEnable true osPageCacheBusyTimeOutMills 3000sendMessageThreadPoolNums8增加并发处理能力但实际并发度仍受 CommitLog 锁限制waitTimeMillsInSendQueue500增加排队容忍时间避免短时毛刺触发快速失败osPageCacheBusyEnabletrue让 Broker 感知 PageCache 压力压力大时自动降速第二层客户端侧重试 超时控制// 设置超时和重试producer.setRetryTimesWhenSendFailed(3);producer.setRetryAnotherBrokerWhenNotStoreOK(true);// 发送时指定超时SendResultresultmqProducer.send(msg,3000);第三层磁盘 IO 治理长期方案使用 SSD 替代 HDD——IOPS 提升 10~100 倍独立磁盘部署 CommitLog 和 ConsumeQueue避免读写相互干扰调整内核 PageCache 参数vm.dirty_ratio、vm.dirty_background_ratio完整配置对比验证结果配置调整并重启 Broker 后确认情况关键指标对比指标优化前优化后说明putMessage 0~50ms 占比0%52.3%大部分消息在内存级完成putMessage 200ms 占比67.6%0.3%长耗时消息基本消失队列排队时间500~1892ms12~31ms积压完全消除队列积压大小957~35675~15处理速度匹配了输入速度SYSTEM_BUSY 次数大量0错误彻底消失注意putMessageDistributeTime中仍有 3 次 500~1000ms 的分布——这是不可避免的当 PageCache 周期性脏页回写时个别消息仍可能遇到短暂的 IO 阻塞。但占比从 18.5% 降到了接近 0说明问题是可接受的。Broker 日志也验证了恢复Accept send request, period in queue: 12ms, size of queue: 5——消息处理恢复了正常节奏。团队在群里确认了修复结果并总结了后续改进措施避坑建议部署 RocketMQ 后立即修改默认线程池sendMessageThreadPoolNums默认 1 极度保守根据 CPU 核数和消息量至少设为 4~8不要忽视osPageCacheBusyEnable默认 false 不感知 PageCache 压力建议设为 true 实现自动流控客户端必须加重试和超时任何中间件都可能短暂不可用重试是容错标配压测要贴近生产测试环境 500 TPS 不能代表 8000 TPS 生产场景压测流量至少为目标峰值的 1.2 倍监控 Broker 端的 putMessage 耗时这个指标是 Broker 健康度的风向标超过 50ms 就应该警惕CommitLog 和 ConsumeQueue 分开磁盘避免读写 IO 互相争抢关注磁盘 IO 的 %util 和 await超过 80% util 或 await 10ms 说明磁盘已经是瓶颈启用BrokerFastFailure默认开启确保短时间积压不会无限排队但waitTimeMillsInSendQueue不宜过短附完整命令清单# 1. 查看应用日志tail-n100trade-service.log|grep-EERROR|system.busy|SYSTEM_BUSY# 2. 查看 Broker 日志tail-n200broker.log|grep-EWARN|wait too long|SYSTEM_BUSY# 3. 系统资源top-bn1|head-20# 4. IO 和内存vmstat16iostat-x13# 5. Broker 运行时状态mqadmin getBrokerRuntime-b{broker_ip}:10911# 6. 查看 Broker 配置catbroker.properties|grep-EsendMessageThread|waitTime|pageCache# 7. 线程栈分析jstack{pid}|grep-A30SendMessageThread# 8. 查看磁盘挂载lsblk|grepsdcdf-h/data/rocketmq/store
w0d0)
