RobustMQ Raft 状态机性能排查:问题不在 RocksDB,在排队
问题的起点
RobustMQ 的 Meta Service 基于 OpenRaft 实现,负责存储 MQTT Session、订阅关系、集群元数据等需要强一致性的数据。选型时我们看过 OpenRaft 官方的性能报告,数字相当漂亮——单节点可以跑到几十万 QPS,延迟在微秒级。
但在我们实际压测中,情况完全不同。
压测 MQTT 大量客户端连接场景时,吞吐虽然能跑到 9000 ops/s,但延迟完全不对——p95 稳定在 360ms 以上,p99 超过 450ms,而且随时间缓慢上涨,没有收敛迹象。官方 benchmark 宣称的是微秒级延迟、几十万 QPS,和我们看到的差了两个数量级。
这个场景下,每个客户端连接都会触发一次 client_write,把 Session 数据写入 Raft 状态机持久化。连接数一上来,Raft 写入压力就直接暴露出来。
我们用 RobustMQ 自带的 cli-bench 工具压测,直接打 Meta Service 的 placement-create-session 接口:
cargo run --package cmd --bin cli-bench meta placement-create-session \
--host 127.0.0.1 \
--port 1228 \
--count 1000000 \
--concurrency 3000 \
--timeout-ms 3000 \
--output table100 万次写入,3000 并发,超时 3 秒。输出如下(节选):
sec=56 | ops/s=8957 | p95=359ms p99=452ms
sec=60 | ops/s=8828 | p95=361ms p99=453ms
sec=70 | ops/s=9092 | p95=367ms p99=457ms
sec=75 | ops/s=12148 | p95=370ms p99=456ms
sec=82 | ops/s=2943 | p95=372ms p99=475ms ← 突然跌落
sec=83 | ops/s=7684 | p95=378ms p99=551ms ← p99 飙升
sec=84 | ops/s=8633 | p95=380ms p99=552ms几个直接观察:
- 稳定吞吐约 9000 ops/s,3000 并发下符合 Little's Law:
3000 / 0.36s ≈ 8333 - p95 从 359ms 缓慢爬升到 372ms,p99 从 452ms 爬升到 457ms,延迟在持续上涨,没有收敛的迹象
- 第 82 秒出现明显抖动:ops/s 跌到 2943,p99 随后维持在 550ms 以上的高位,推测是 RocksDB compaction 或后台 flush 触发了短暂的写阻塞
这个差距让我们困惑了一段时间。我们用的是同一个库,实现上也没有明显的异常,为什么性能差这么多?是我们写的有问题,还是 OpenRaft 本身在生产环境下就是这样?还是说,这个延迟有其他原因?
这篇文章记录我们排查这个问题的过程。
排查过程:一步步加监控,一步步排除
遇到性能问题,直觉往往不可靠。我们经历了几轮"以为找到了,结果不是"的过程。
第一步:怀疑 gRPC Server 并发处理能力
3000 并发请求打过来,最先怀疑的是 gRPC Server 本身有并发瓶颈——比如处理队列满了、连接数有上限、或者某个请求长时间占用导致后续请求堆积。
查了 tonic 的文档和代码,tonic gRPC server 本身没有硬性的并发连接限制,底层是 HTTP/2 多路复用,理论上可以在一条 TCP 连接上并发处理大量请求。
但"没有限制"不等于"没有问题",缺少可观测性才是真正的问题——请求到了服务端之后处理了多久,成功率多少,完全看不到。
于是在 gRPC Server 的 BaseMiddleware(Tower 中间件层)里加上了请求级别的耗时统计:每个请求完成后记录耗时到 grpc_request_duration_ms Histogram,同时把请求数(grpc_requests)按 service/method/status 维度记录。另外加了慢请求告警——超过 2000ms 的请求打一条 warn 日志,方便从日志里直接发现异常。tonic Server 也补上了 HTTP/2 keepalive 和 30s 超时配置。
加完之后,Grafana 上的 gRPC Server QPS、错误率、延迟分布都能看到了。数据显示 gRPC Server 的处理延迟本身很低,请求都在正常响应,没有阻塞或堆积。
gRPC Server 并发问题排除。
第二步:怀疑 gRPC 连接池
cli-bench 通过 gRPC 调用 Meta Service,3000 并发请求打过来,下一个怀疑是客户端连接池太小,请求在发出去之前就在排队。
查日志发现确实出现过 transport error 和连接数卡在 5 不增长的情况。分析后发现原因:原有实现基于 mobc 库,Pool::builder() 只配置了 max_open,缺少 max_lifetime 和 max_idle_lifetime,导致死连接不会被回收,池子扩不起来。
于是做了一次比较大的改造:直接去掉 mobc,用 Vec<Channel> + AtomicUsize round-robin 自己实现了一个轻量连接池(ChannelPool)。tonic 的 Channel 底层是 HTTP/2 多路复用,不需要像数据库连接那样维护大量 TCP 连接,每个地址保持几个 Channel 做 round-robin 分发就够了。同时把连接池的监控指标加上,观察 channel 数量和获取耗时。
改完后连接池行为正常,压测日志里 transport error 消失。但延迟没有任何变化。
连接池排除。
第三步:怀疑 RocksDB 性能,加 RocksDB 监控
连接池没问题,往服务端找。直觉上 RocksDB 是最容易出问题的地方——写放大、WAL 刷盘、compaction 都会造成毛刺。
RobustMQ 在 RocksDB 的 save / get / list / delete 操作上都有 Histogram 打点(rocksdb_operation_ms),把 Grafana 上的 RocksDB Write Latency 和 RocksDB Read Latency 面板调出来。
压测期间 RocksDB 的写入延迟稳定在 1ms 以内,读取也正常,没有出现 compaction 阻塞或 WAL 延迟的迹象。
RocksDB 排除。
第四步:发现 Raft Write Latency 很高
既然存储层没问题,往上看。src/meta-service/src/raft/manager.rs 里本身就有对 client_write() 的耗时统计,记录到了 Prometheus Histogram。
把 Grafana 上的 Raft Write Latency 面板调出来:P50 稳定在 89ms,P99 到了 243ms,P999 到了 460ms。问题不在网络传输,就在 Raft 写入本身。
但 Raft 内部还是黑盒——是共识慢?是状态机 apply 慢?是某个地方在阻塞?不知道。
第五步:加上系统 CPU 和内存监控
怀疑是机器资源打满导致整体调度变慢。加上了进程 CPU 使用率、系统 CPU 使用率、进程内存、系统内存的监控面板。
压测期间数据出来:System CPU 打到了 100%,Process CPU 只有 40%,两者差了 55%。
这个差值很关键。Broker 自己只用了 40% CPU,另外 55% 是压测工具(跑在同一台机器上)消耗的。两个进程在互相抢 CPU,测出来的延迟有一部分是环境干扰,不完全是 Broker 的真实瓶颈。这也说明后续压测需要分机部署,才能看到 Broker 的真实上限。内存方面没有异常,排除内存压力。
第六步:加上 Tokio Runtime 监控
CPU 资源是被两个进程共享消耗的,那 Broker 内部的 40% CPU 又是怎么分布的?各个子系统有没有相互干扰?
加上了各个 Tokio Runtime 的 busy ratio、global queue depth、alive tasks 的监控面板。
数据出来三条曲线表现很不一样:server-runtime busy ratio 在 40~80% 之间波动,meta-runtime 在写入量冲高时有明显尖刺,broker-runtime 接近 0%。
这组数据确认了两件事:一是三个 runtime 的隔离生效,Raft 的负载没有溢出到 server-runtime;二是 server-runtime 虽然繁忙,但没有饱和——网络处理层本身不是瓶颈。
第七步:观察 Apply Lag 和 Write Latency 的联动
给监控加上了 raft_apply_lag(last_log_index - last_applied 的差值)、raft_last_log_index、raft_last_applied 三个 Gauge 指标,观察状态机是否在积压。
两张图放在一起对比很有说明力:Apply Lag 的飙升总是早于 Write Latency 的上涨。mqtt 写入量冲到 6K req/s 时,Lag 先堆积到 71,随后 Write Latency 才从 300ms 爬升到 1s 以上。
说明是状态机 apply 跟不上,产生反压,进而拖慢了 client_write 的整体耗时。
第八步:想通过 CPU 火焰图进一步定位
项目里有 pprof 集成(src/common/pprof-monitor),开启后可以通过 HTTP 接口实时拉取火焰图,看各函数的 CPU 占比。
这条线没有继续深入,因为有了更直接的方式——把链路直接拆开打点。
第九步:把 client_write 链路分段计时,找到那 199ms
client_write 整体花几百 ms,但哪段最慢仍然不清楚。链路拆开大致是:
client_write()
→ RaftCore 处理 propose
→ 写 Raft log(log append) ← 在这里打点
→ commit 推进
→ 通知状态机 apply
→ 状态机写 RocksDB(apply batch)← 在这里打点
→ 返回在 log.rs::append() 和 state.rs::apply() 分别加了批次级别的计时:只在函数入口和出口各一次 Instant::now(),结果上报到 Prometheus Histogram,Grafana 上新增 raft_log_append_batch_duration_ms 和 raft_apply_batch_duration_ms 两个面板。不做每条 entry 的细粒度统计,热路径上只有两次时钟读取,开销可以忽略不计。
数据说明了什么
新增的两个面板数据出来,结论非常清晰:
raft_log_append_batch_duration_msP50:0.5msraft_apply_batch_duration_msP50:0.5msraft_write_duration_ms(client_write 整体)P50:200ms,P99:431ms,P999:615ms
两端加起来不到 1ms,端到端却要 200ms,中间差了 199ms。
这直接排除了 RocksDB 的嫌疑。RocksDB 写入没有问题,问题在 Raft 内部的调度和等待。
199ms 花在哪里
理清楚 OpenRaft 的内部实现之后,答案就清楚了。
OpenRaft 的核心是一个单线程 Actor(RaftCore),所有 propose、commit、apply 通知都通过 async channel 传递,由这个单线程串行处理。这是 Raft 算法正确性的要求——Leader 必须对所有 entry 维护一个全局有序的视图,并行处理会破坏这个约束。
当一个 client_write 请求进来,它的生命周期大概是这样的:
- 进入 RaftCore 的 mailbox,等待被调度
- RaftCore 处理 propose,写 log(0.5ms)
- 等待 commit 确认
- 通过 channel 通知 apply task
- apply task 执行状态机写入(0.5ms)
- 通过 channel 把结果返回给调用方
步骤 2 和步骤 5 加起来 1ms。步骤 1 的等待时间在低负载下微乎其微,但在高 QPS 下,RaftCore mailbox 里积压的请求越来越多,步骤 1 的等待时间就成了延迟的主体。
用排队论的公式来理解:在 M/M/1 队列模型下,
平均响应时间 = 服务时间 / (1 - 利用率)apply 耗时 0.5ms,RaftCore 的理论最大吞吐约 2000 QPS。3000 并发下系统实际跑到 9000 ops/s,靠的是队列积压来"堆"吞吐。此时利用率(ρ)接近 1,分母趋近于 0,延迟趋近于无穷。
即使 ρ = 0.9(还没过载),平均响应时间也是 0.5ms / 0.1 = 5ms。ρ = 0.99 时是 50ms。队列效应对高利用率极度敏感,这和 OpenRaft 本身无关,是单线程处理器面对高并发时的普遍规律。
Raft 状态机的性能上限真的只有 2000 QPS 吗
分析到这里,一个自然的反应是:单个 Raft group 加上 RocksDB,性能就只有 2000 QPS?这也太低了。
这个结论有一个隐含前提没说清楚,值得展开。
2000 QPS 是"每轮处理一条"的极限,不是 Raft 的上限
RaftCore 是单线程 Actor,一轮处理流程约 1ms(0.5ms log append + 0.5ms apply)。但 OpenRaft 天然支持批处理——当多个请求同时积压在 mailbox 里,RaftCore 会把它们合并成一个批次,用一次 WriteBatch 写 RocksDB,一次 apply() 调用处理所有 entry。
吞吐的真实公式是:
吞吐 = (每秒处理轮数) × (每轮平均 batch size)
= 1000 轮/秒 × N 条/轮N=1 时是 1000 QPS,N=50 时就是 50000 QPS。每轮的 batch size 才是决定吞吐的关键变量。
这也解释了我们实测 9000 ops/s 是怎么来的:3000 并发把 mailbox 撑起来之后,每轮可以处理多条 entry,吞吐远超单轮极限,代价是 360ms 的高延迟。系统在用堆并发、拉高 batch size 的方式"借"来的吞吐,但借的代价是排队延迟。
RocksDB 本身不是瓶颈
NVMe SSD 上 RocksDB 的 WriteBatch 吞吐轻松到 100k 写/秒以上。真正慢的是 WAL 的 fdatasync——Raft 的持久化语义要求每个 batch 写完都要 sync 到磁盘。NVMe 上 fdatasync 约 0.1~0.5ms,HDD 上约 5~10ms。批次越大,fdatasync 的摊销成本越低,吞吐越高。
etcd 建议 1000 QPS 是保守的稳定性建议
etcd 文档里推荐生产环境写入不超过 1000 QPS,不是硬上限,而是给 compaction、snapshot、follower 同步留足余量,避免长尾抖动。etcd 在实验室环境下单节点可以跑到 10k~30k ops/s。
那我们的 2000 QPS 限制从哪里来
是当前实现的约束,不是 Raft 或 RocksDB 的普遍约束。RobustMQ 目前每个 client_write 只写一条 entry,低并发下 batch size 接近 1,自然撞上了单轮极限。改法很直接:应用层批量合并,把同一客户端连接周期内的多个写操作打包进一次 client_write,让 batch size 从 1 变成 10~50,吞吐有数量级的提升空间,同时延迟也会随之下降,因为每个请求等待的轮数减少了。
和官方 benchmark 的差距
到这里,最初的困惑可以解释清楚了。
OpenRaft 官方 benchmark 的测试配置是内存 state machine,apply 操作接近 0 耗时。在这个前提下,理论最大 QPS ≈ 100 万次/秒,系统利用率很低,排队效应几乎为零,延迟当然是微秒级。
我们的实现是 RocksDB state machine,每批次 apply 约 0.5ms,但这 0.5ms 是可以被多条 entry 共享的批次成本。真正的差距在于:内存操作接近 0 耗时,磁盘 fdatasync 约 0.5ms,这个 500 倍的差距决定了单轮处理能力的天花板。
官方 benchmark 测的是 OpenRaft 协议层本身的开销,不反映接入真实存储后的性能。两者不是一个维度的测试,直接对比没有意义。
补充:Tokio Runtime 隔离与监控
这次排查里,Tokio Runtime 的监控数据是重要的一块拼图。值得单独展开说,因为这对 Rust 大型服务的性能分析有通用价值。
为什么要做 Runtime 隔离
RobustMQ 是一个包含多个子系统的大型服务进程:gRPC Server、OpenRaft 状态机、MQTT Broker 业务逻辑在同一个进程里运行。OpenRaft 启动时会通过 tokio::spawn 创建约 9 个内部 task(core loop、log IO、state machine worker 等),这些 task 绑定到 Raft::new() 被调用时的 runtime context。如果在 server_runtime 上初始化,这 9 个 task 就会和 gRPC 请求处理的 task 混在一起,相互争夺 worker 线程。
RobustMQ 的做法是拆成三个独立的 runtime:
server-runtime → gRPC server、网络 I/O、请求分发
meta-runtime → OpenRaft 全部内部 task、RocksDB 元数据写入
broker-runtime → MQTT 业务逻辑、消息处理初始化时明确在 meta_runtime 的上下文里调用 Raft::new(),确保 Raft 的所有内部 task 绑定到 meta_runtime,不会污染 server_runtime:
let meta_runtime = create_runtime("meta-runtime", meta_worker_threads);
let meta_params = meta_runtime.block_on(BrokerServer::build_meta_service(...));监控什么
Tokio 提供了 tokio::runtime::Handle::metrics() API。我们基于此实现了 start_runtime_monitor,每 15 秒采一次样,上报三个指标:
- Busy Ratio:通过对比相邻两次采样的
worker_total_busy_duration差值,计算 worker 线程的实际繁忙占比。0% 是完全空闲,100% 是所有线程一直在跑 - Global Queue Depth:待执行 task 在全局队列里积压了多少,是 runtime 过载的早期信号
- Alive Tasks:当前存活的 task 数量,异常增长说明某处在无节制地 spawn
数据说明
压测期间三条曲线表现差异明显:server-runtime busy ratio 40~80%,meta-runtime 写入冲高时有尖刺,broker-runtime 接近 0%。这确认了两件事:隔离生效,Raft 负载没有溢出到 server-runtime;server-runtime 繁忙但未饱和,网络处理层不是瓶颈。
如果没有 runtime 隔离,三条曲线会叠成一条,根本看不出哪个子系统在消耗资源。
结论
问题是什么
用 3000 并发压测 Meta Service 的 Session 写入,吞吐能跑到 9000 ops/s,但 p95 延迟 360ms 且随时间持续上涨,和 OpenRaft 官方 benchmark 宣称的微秒级延迟差了两个数量级。
排查了什么,排除了什么
先后加上了 gRPC Server 请求指标、gRPC 连接池指标、RocksDB 操作延迟指标、进程/系统 CPU 内存指标、Tokio Runtime busy ratio 指标、Raft apply lag 指标,最后在 log.rs::append() 和 state.rs::apply() 两处加了批次计时。
排除链路:gRPC Server 无异常 → 连接池去掉 mobc 重写后正常 → RocksDB 写入 < 1ms 正常 → CPU/内存不是主因(压测工具占了 55% CPU)→ Tokio Runtime 未饱和 → Apply Lag 确认积压存在 → 分段计时找到 199ms 在排队。
根本原因
log append 实测 0.5ms,apply batch 实测 0.5ms,但 client_write 端到端 200ms,差了 199ms。这 199ms 花在 RaftCore 的 mailbox 排队上。RaftCore 是单线程 Actor,apply 耗时 0.5ms 决定了理论上限约 2000 QPS,3000 并发下系统在满载边缘运行,队列效应把 0.5ms 放大成了几百毫秒。
性能边界和下一步
2000 QPS 是"每次 client_write 写一条 entry、batch size = 1"时的单轮极限,不是 Raft 的上限。实测 9000 ops/s 是 RaftCore 批量处理多条 entry 的结果,代价是 360ms+ 的排队延迟。解法有两个方向,效果不同:
应用层批量写是治标:把多个 MQTT 操作合并进一次 client_write,batch size 从 1 提到 10~50,吞吐提升,延迟也会改善,但单个 RaftCore 仍然是一个串行瓶颈,上限在那里。
Multi-Raft 分片是治本:把 Session 写入按 ClientID 哈希分散到多个独立 Raft group,每个 group 有自己的 RaftCore,相互之间完全并行。10 个 group 就是 10 倍吞吐,延迟也能保持在低位,因为每个 group 的队列压力都降低了。这才是真正的水平扩展。
RobustMQ 在架构上已经做了 Multi-Raft 的设计——元数据、MQTT 状态、Offset 各自有独立的 Raft group,不同类型的数据之间已经隔离。但目前所有 MQTT Session 写入仍然打到同一个 group,group 内部还是单 RaftCore 的串行瓶颈。
下一步是把这个设计真正利用起来:在 Session 这类高频写入的数据类型上,按 ClientID 哈希分片到多个 group,让多个 RaftCore 并行处理。这比批量写更彻底,也是 TiKV、CockroachDB 这类生产级分布式系统解决单 Raft 瓶颈的标准路径。
短期:应用层合并写,减少单 group 的处理轮数。
中期:梳理哪些操作不需要强一致性,从 Raft 路径上移走。
长期:Session 等高频写入按 ClientID 分片到多个 group,把 Multi-Raft 设计真正跑起来。
