「越跑越慢」的 Go 服务：一次锁竞争事故的完整复盘

发表于

引子

最近做一个区块链数据回放（replay）任务：把历史区块数据灌进 Mongo，中间层是一个 Go 写的 ingest 服务（下文简称 batcher）。任务刚启动时跑得飞快，但吞吐一路下滑，25 个小时只前进了 9 个百分点，最终定位到一个非常典型的 Go 并发问题——持锁的 O(N) 全表扫描 + 只增不删的 map。

这篇文章包含完整的事故时间线、一套可复用的诊断方法论，以及从零讲起的锁知识，希望对遇到同类问题的朋友有帮助。

事故时间线

第一天：启动与一次「治愈」的假象

时间 事件 关键数据
08-24 01:01 2000 万块 replay 启动，监控脚本上线 早期区块处理极快
08-24 01:01~02:41 2% → 10%（40 万 → 200 万块）。前 193 万块是幂等覆盖旧数据，Mongo 计数不变 Mongo ops 恒为 135 万
08-24 02:41 → 08-25 03:32 爬行期：10% → 19.5%（25 小时只走了 190 万块 ≈ 21 块/秒） 吞吐 ~50 ops/s
08-25 ~04:00 第一轮诊断启动 生产者 CPU 0.02%、batcher 146%、Mongo 7.6%；Mongo 单次批量写仅 21ms；生产者持续报 Ingest queue full
08-25 ~05:38 第一次处置：旧镜像打 rollback 标签 → 用当前代码重建 → 热替换容器 —
08-25 05:38~05:50 「痊愈」：12 分钟 9011 批 ≈ 1250 ops/s，batcher CPU 49%，生产者 100% 当时误判为「旧镜像 CPU 空转」，还写进了周报
08-25 白天 按新速度估算 ETA ~1.5 天，继续监控 —

第二天：复发与真相

时间 事件 关键数据
08-25 17:12 再次查进度 → 发现复发：吞吐掉回 630 批/10min ≈ 105 ops/s，queue full 持续 总 ops 2077 万 / 11.1GB，进度 30.5%（610 万块）
08-25 17:12~17:20 第二轮诊断：三个假设连环证伪 + procfs 尸检 + 代码定位（见下文） 7 个线程各累计 15~48 分钟 utime，全部停在 futex_do_wait；grep delete( 零结果
08-25 ~17:22 修复上线：分支 fix/batcher-pending-blocks-leak → build/test 通过 → --force-recreate 热替换 1 个文件 +31/-34
08-25 17:33 首验（10 分钟窗口）：8385 批 ≈ 1400 ops/s，queue full 0，服务内存 18.2MiB（原来 450MB+），batcher CPU 22%，生产者 101% —
08-25 ~17:45 PR #51 提交、确认、合并 —
08-26 00:09 长期验证通过：修复 6.5 小时后仍 1430 ops/s（bug 版在同等时长内已劣化到两位数）；replay 推进到 **53%**（1060 万块 / 5294 万 ops） —

关键认知转折：第一天的「换镜像提速 25 倍」其实是重启清空了 map 的假象。
劣化速率 ∝ 已见块数（N），与进程年龄、镜像新旧无关——第二天它按同样的曲线再次趴下，
才把怀疑对象从「二进制」纠正为「代码」。

地基概念：锁、自旋与 futex

为什么需要锁

batcher 是 Go 程序：每个 HTTP 请求一个 goroutine（轻量线程），外加定时器 goroutine，它们并发读写同一份内存。Go 的 map 不允许并发读写混用，轻则数据错乱，重则进程崩溃，所以需要锁。

读写锁 sync.RWMutex（图书馆阅览室模型）

  • RLock（读锁）= 进来看书，多人可以同时在场；
  • Lock（写锁）= 搬桌子改结构，必须清场独占。
  • 规矩：读读兼容 / 读写互斥 / 写写互斥。

自旋（spin）

goroutine 抢不到锁时，Go 运行时先「原地转圈」重试若干轮再睡觉。竞争越激烈、临界区越长，越多 goroutine 空转烧 CPU——没干活，电费照付。本次事故中 124%~146% 的 CPU 大部分是这个。

futex

Linux 上锁的实现原语。线程停在 futex_do_wait = 此刻正在等一把锁。utime（用户态 CPU 时间）很高 + 此刻停在 futex 等待 = 历史上大量自旋，现在在排队。

O(N)

操作成本随数据量 N 线性增长。锁内 O(N) 操作是性能事故的经典配方。

原始设计解剖：每块都合理，合起来是炸弹

1
2
3
4
5
6
type Batcher struct {
    blocks          map[uint32]*blockInfo  // 见过的【所有】块的信息
    blocksMu        sync.RWMutex
    blocksWritten   map[uint32]bool        // 已写入 Mongo 的标记
    blocksWrittenMu sync.RWMutex
}

三个部件，单看都有道理：

  1. AddBlockInfo — 每个操作到达时登记块信息（写锁），设计正确；
  2. flushBatch — 批量落库时查出涉及的块连带写入，并在 blocksWritten 打勾，设计正确；
  3. flushUnwrittenBlocks — 定时器每 tick 扫一遍 blocks，把没打勾的（空块）补写；意图善良，实现有毒：
1
2
3
4
5
b.blocksMu.RLock()        // ← 读锁，整个扫描期间持有
b.blocksWrittenMu.RLock() // ← 第二把读锁
for blockNum, blockInfo := range b.blocks {   // O(N) 全表扫描
    if !b.blocksWritten[blockNum] { ... }      // 每条再查一次另一个 map
}

问题不在任何单个部件，而在缺了第四个部件——销毁。内存数据应有完整生命周期：出生（登记）→ 使用（落库）→ 死亡（删除）。这份代码只有前两步：

1
grep -n "delete(" batcher.go    # 输出：空。两个 map 永远只进不出。

叠加效应：

  • 每 tick 扫描成本 O(N)，N = 见过的块总数，随链高度线性增长；
  • 扫描全程持读锁 → 所有 AddBlockInfo（写锁）排队 → goroutine 自旋堆积；
  • 600 万条目时，每秒一次的全表扫描吃掉约一个核，锁排队雪崩。

为什么历史测试没发现：200 万块时 N 小，慢被淹没在噪声里；单元测试根本跑不到「数百万条目 × 数小时」的规模。此类 bug 属于生命周期泄漏型性能 bug，只在「规模 × 时间」上显形。重启清空 map 即恢复满速——这又制造了「换镜像治好了」的强烈误导。

诊断方法论：每一步都可以复用

1. 量化症状

从日志数批次：630 批/10min ≈ 105 ops/s（健康基线 8385 批）。先有数字，之后每个假设都用数字检验。

2. 三层 CPU 快照——「谁在忙」比「谁慢」更有指向性

1
2
3
生产者（steemd）   CPU  13%    ← 本该满速，却闲着 = 被下游勒住
batcher（中间层）  CPU 124%    ← 烧 1.2 核
Mongo（存储）      CPU  7.5%   ← 几乎闲着

读法：下游闲、中间烧、上游被勒 → 瓶颈在中间层。若 Mongo 是慢源，Mongo CPU 应打满；若生产者自身慢，中间层不该忙。

3. 用对端指标连环证伪

假设 铁证 判决
Mongo 写得慢？ 自测单次批量写 21→53ms，28h 内 Mongo 忙碌率 ~2% ❌
换的镜像不对？ 容器镜像 ID 与构建产物完全一致 ❌
2017 年区块数据变大、解析变慢？ 批次字节 300→450 B/op，差 2 倍解释不了 13 倍劣化 ❌
GC 压力？ 30 秒 1 次 GC、分配仅 1.2MB/s ❌

心法：别找「谁的嫌疑最大」，找「谁有铁证不在场」。每证伪一个，范围收窄一圈。

4. procfs 尸检（没有 pprof 时的核武器）

服务没开 pprof，但内核把证据免费放在 /proc：

1
2
/proc/<PID>/task/<TID>/stat   # 每线程累计 utime/stime
/proc/<PID>/task/<TID>/wchan  # 此刻阻塞在哪个内核函数

现场：

1
2
7 个线程，各累计 15~48 分钟 utime（大量用户态计算）
此刻全部停在 futex_do_wait（= 在等锁）

结论收敛为一句话：有人在持锁做一件又长又无聊的事——utime 高（烧过 CPU）+ futex（在等锁）+ GC 安静（烧的不是正业）= 锁竞争自旋。

5. 带画像回代码，一击定位

「持锁扫描一个不断增长的结构」→ grep delete( 零结果（只增不删）→ flushUnwrittenBlocks 每 tick 全表扫 + 双 RLock → 与尸检画像完全吻合。结案。

手术：两条铁律与并发安全论证

两条铁律：

  1. 临界区只做 O(1) 的事 — 拿锁的范围缩到最小最快；
  2. 内存数据要有死亡 — 用完即删，让「存在即未处理」成为不变量。

修复（PR #51，1 个文件）：

1
2
3
4
5
6
7
// 旧：blocks 只进不出 + blocksWritten 打勾（两个真相源，永不收缩）
// 新：块写库成功后立即 delete(b.blocks, blockNum)
b.blocksMu.Lock()
for _, block := range blocksToWrite {
    delete(b.blocks, block.BlockNum)
}
b.blocksMu.Unlock()

blocksWritten 整体删除：「还在 map 里」本身就等于「没写过」，一个真相源够了。两个 map 互相印证看似严谨，实则双倍内存、双把锁、还要维护一致性。失败写入不删条目 → 下个 tick 自动重试，原有语义保留。

修锁代码的最后一步永远是穷举交错的并发安全论证：同一块号的信息是确定性的（同一块必同 ID/时间戳），任何「写成功→删除」与「另一批次重新登记同一块」的交错，最坏只是相同内容幂等多写一次，不存在丢数据的交错序列。

修复前后实测对比：

指标 修复前 修复后
吞吐 ~105 ops/s ~1400 ops/s，6.5h 后仍 1430
queue full 持续 0
服务内存 450MB+ 随进度增长 18~22MiB 恒定
服务 CPU 124%（自旋） 22~31%
生产者 CPU 13%（被背压） ~101%（天然瓶颈）

通用心法（带走这四条）

  1. 锁问题很少崩溃，多是「越跑越慢」。吞吐随运行时长下降 → 第一怀疑「某结构悄悄增长 + 有人持锁扫它」。
  2. 诊断「慢」的起手式：三层 CPU + 对端延迟。生产者/中间层/存储各拍一个 CPU，再看存储自己的耗时指标；谁烧谁闲，指向性极强。
  3. 重启能治好的病，别归因给「版本」。重启清空进程内状态，治好的往往是状态累积型 bug，与二进制无关——本次第一天就掉进了这个坑，浪费了一次归因正确的机会。
  4. 长跑测试的价值不止于数据。这次 2000 万块 replay 最大的副产品是逼出了一个单元测试永远测不出的 bug——「数据深度试验」最坚实的理由。

附：涉及的命令速查

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
# 三层 CPU
docker stats --no-stream --format "{{.Name}}: CPU {{.CPUPerc}} MEM {{.MemUsage}}" <生产者> <中间层> <存储>

# 吞吐计数（按日志特征行）
docker logs <容器> --since 10m 2>&1 | grep -cE "BATCH success"

# 进程尸检
PID=$(docker inspect <容器> --format '{{.State.Pid}}')
for t in /proc/$PID/task/*/stat; do
  awk '{split($2,a,"("); split(a[2],b,")"); if ($14+$15>100) print b[1], "utime="$14, "stime="$15}' $t
done
cat /proc/$PID/task/<TID>/wchan

# 只增不删体检
grep -n "delete(" <文件>

# 热替换（幂等 upsert + 对端重试为前提）
docker compose build <service> && docker compose up -d --no-deps --force-recreate <service>