HDUO Lab

深度还原：PageCache 抖动引发的 CommitLog 写入雪崩——从 RocketMQ 事务消息回查机制说起

作者：

ningniu

在

凌晨两点一刻，刚把监控大盘从主屏切到后台，准备过一遍明天的变更脚本，手机和值班群同时炸了。

告警内容很直接：订单核心链路的 RocketMQ 集群大面积报 Producer Send Timeout，发送 RT 的 P99 从平时的 2ms 飙升到了 3000ms 以上。

连上 VPN，切到生产环境跳板机。这套集群支撑着交易核心，不容闪失。我扫了一眼 Grafana，Broker 的网络入流量并没有明显突增，但系统负载（Load Average）却异常起飞，特别是 CPU 的 iowait 比例出现剧烈锯齿。

迅速敲击命令进入故障 Broker 节点，开始现场勘探。

现场勘探：是谁锁死了 CommitLog？

进入 Broker 日志目录，tail -f broker.log，满屏都是刺眼的 [OS_PAGECACHE_BUSY] 和 [TIMEOUT_CLEAN_QUEUE]。

2023-10-27 02:18:05 INFO SendMessageThread_1 - [OS_PAGECACHE_BUSY] broker busy, start flow control for a while
2023-10-27 02:18:05 WARN SendMessageThread_2 - [TIMEOUT_CLEAN_QUEUE]broker busy, start flow control for a while, period in queue: 205ms, size of queue: 876

RocketMQ 抛出 OS_PAGECACHE_BUSY 的条件很明确：当往 CommitLog 写入消息时，获取锁的时间超过了设定的阈值（osPageCacheBusyTimeOutMills，默认 1000ms）。

我检查了 Broker 的核心配置：

flushDiskType=ASYNC_FLUSH
transientStorePoolEnable=false
useReentrantLockWhenPutMessage=false

这里使用的是异步刷盘，而且 useReentrantLockWhenPutMessage 为 false，意味着 RocketMQ 内部使用的是自旋锁（SpinLock）来保证 CommitLog 写入的串行化。

这就解释了为什么 Load 会飙高：当某个线程因为某种原因在 putMessage 阶段被卡住超过 1 秒，持有自旋锁不释放，后续成百上千的 Producer 线程会在 CPU 上疯狂自旋等待，直接把系统 Load 打爆。

但这只是表象。写入是在内存（PageCache）中进行的，按理说只有微秒级的延迟，为什么会被卡住这么久？

看看系统的 I/O 状态：

$ iostat -dxm 1
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
nvme0n1           0.00     0.00 4500.23  120.45   180.50    15.20    85.45     8.50   18.20   20.10    2.50   2.10  98.50%

磁盘 %util 接近 100%，但诡异的是，wMB/s（写吞吐）只有 15MB/s，而 rMB/s（读吞吐）居然高达 180MB/s。

一个核心的消息接收节点，为什么会有这么大的随机读？

抽丝剥茧：事务消息回查引发的冷读风暴

用 pidstat -d -t 1 抓一下具体的线程 I/O：

$ pidstat -d -t 1 -p $(jps | grep BrokerStartup | awk '{print $1}')
...
15:20:01      UID      TGID       TID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
15:20:02     1001         -     10245 185200.00      0.00      0.00      45  TransactionMess
...

破案的第一步：罪魁祸首是 TransactionMessageCheckService 线程。

这是 RocketMQ 处理事务消息回查的后台线程。结合业务背景，凌晨 1 点左右，下游的一个账户服务做过一次平滑重启，期间网络出现了短暂的闪断，导致订单系统发出了大量的 Half 消息（预备事务消息），但没有收到最终的 Commit/Rollback。

在 RocketMQ 的内核实现中，事务消息的底层逻辑是这样的：

  1. 真实的 Topic 和 QueueId 被隐藏，消息先被写入名为 RMQ_SYS_TRANS_HALF_TOPIC 的系统 Topic。

  2. 业务执行本地事务，向 Broker 发送二阶段确认。如果是 Commit，Broker 会把消息恢复成真实的 Topic 并投递；如果是 Rollback，则废弃。

  3. 如果二阶段确认丢失，TransactionMessageCheckService 会定期扫描 Half Topic。

问题就出在回查上。

当回查线程扫描到未决的 Half 消息时，它需要读取原始消息的内容来构造回查请求发送给 Producer。如果这些 Half 消息是几小时前的，或者由于量大导致已经被刷入磁盘的冷区，回查操作就会触发大量的磁盘随机读。

RocketMQ 是基于 Mmap 映射物理文件的。当读取冷数据时，会触发缺页中断（Page Fault），内核必须将磁盘数据加载到 PageCache 中。高达 180MB/s 的冷读，瞬间污染了系统大量的 PageCache。

雪崩的闭环：PageCache 颠簸与 Mlock 阻塞

仅仅是冷读，为什么会阻塞新消息的写入（写 CommitLog）？这就涉及 Linux 内核的内存管理与 RocketMQ AllocateMappedFileService 的底层博弈了。

RocketMQ 为了避免 CommitLog 在写入时动态分配物理内存导致延迟，采用了一套预分配机制：提前通过 Mmap 映射好下一个 1GB 的文件，并调用 madvise 和 mlock 将内存锁定，防止被 Swap 出去。这个过程被称为 warmMappedFile。

源码片段如下（摘自 MappedFile.java）：

public void warmMappedFile(int pages, int flushDiskType) {
    long beginTime = System.currentTimeMillis();
    ByteBuffer byteBuffer = this.mappedByteBuffer.slice();
    int flush = 0;
    long time = System.currentTimeMillis();
    for (int i = 0, j = 0; i < this.fileSize; i += MappedFile.OS_PAGE_SIZE, j++) {
        byteBuffer.put(i, (byte) 0); // 触发 Page Fault，强制分配物理内存
        // force flush when flush disk type is sync
        if (type == FlushDiskType.SYNC_FLUSH) { ... }
    }
    // ...
    this.mlock(); // 调用 libc 的 mlock 锁定内存
}

今晚的灾难是一场精妙的巧合拼图：

  1. 事务回查引发读风暴：大量的冷数据读取，导致 OS PageCache 被迅速耗尽。

  2. 内核触发直接内存回收（Direct Reclaim）：系统内存吃紧，kswapd 疯狂运作，甚至触发了直接回收，导致所有的 I/O 操作变慢。

  3. 预分配线程被卡死：AllocateMappedFileService 在执行 byteBuffer.put(i, (byte) 0) 试图热身下一个 1GB MappedFile 时，由于内存紧缺和磁盘 I/O 极度繁忙，缺页中断陷入深度阻塞。

  4. 当前 CommitLog 写满，Producer 等待：当老的 CommitLog 写满，写入线程向预分配服务索要新的 MappedFile 时，拿不到文件，只能等待。

  5. 自旋锁耗尽 CPU：持有 putMessageLock 的线程在等待，后续发来消息的 Producer 线程在自旋锁上死循环（while (!this.putMessageLock.tryLock())），瞬间打满 CPU。

最终，等待超过 1000ms，Broker 抛出 [OS_PAGECACHE_BUSY]，集群彻底雪崩。

现场止血与底层根治

时间到了凌晨 2:35，原因清楚了，止血是第一要务。

1. 紧急压制回查风暴

不能让 TransactionMessageCheckService 继续肆虐了。我直接通过 mqadmin 命令动态调整该 Broker 的事务回查参数：

# 降低回查频率和单次回查的规模
sh mqadmin updateBrokerConfig -b 10.x.x.x:10911 -k transactionCheckInterval -v 60000
sh mqadmin updateBrokerConfig -b 10.x.x.x:10911 -k transactionCheckMax -v 100

参数下发后不到一分钟，磁盘读吞吐降到了 5MB/s 以内，I/O await 断崖式下降，[OS_PAGECACHE_BUSY] 报错随之停止，生产端的 Send Timeout 告警清零。

2. 架构层面的根治：启用 TransientStorePool

事后复盘，虽然回查风暴是导火索，但 RocketMQ 本身的部署配置也有优化的空间。为了彻底隔离 PageCache 抖动对主写链路的冲击，我们在后续的变更中开启了 transientStorePoolEnable 机制。

修改 Broker 配置：

transientStorePoolEnable=true
transientStorePoolSize=5

开启堆外内存池后，RocketMQ 的写入路径发生了本质变化：

  • 未开启前：Producer 发送消息 -> 追加到 MappedByteBuffer (PageCache) -> Flush 线程异步刷盘。这种模式下，写入直接依赖内核对 PageCache 的分配，极易受缺页中断和系统脏页回写的影响。

  • 开启后：RocketMQ 启动时，直接调用 posix_memalign 在内核中锁定一批 DirectByteBuffer 作为内存池。Producer 的消息直接写入这些已经锁定物理内存的 Direct IO 缓冲中（纯内存操作，无 Page Fault），然后由 CommitRealTimeService 线程异步将 ByteBuffer 里的数据 commit 到 MappedFile (PageCache)，最后再异步 flush 到磁盘。

写入路径与刷盘路径实现了物理内存级别的隔离。哪怕后台 PageCache 抖动成麻花，只要 DirectByteBuffer 池没有耗尽，前端 Producer 的写链路就是丝般顺滑的。

当然，启用 transientStorePoolEnable 的代价是进程重启或机器宕机会丢失还没 commit 到 PageCache 的极少量消息（因为存在于堆外内存中）。但对于强依赖吞吐稳定性的业务，配合 RocketMQ 的多副本机制（如 DLedger 或 Controller 模式的主备），这个 trade-off 是完全值得的。

处理完所有善后工作，确认集群各项指标平滑如镜。看了看时间，已经是凌晨四点。合上电脑终端，下半夜终于可以消停了。运维架构的底色，往往就藏在这一行行内存映射与内核调度的博弈之中。

更多文章