先定义要证明的“慢”
本章的贯穿项目是 arch-lab 订单交易系统。本节只做一件事：把“服务慢”从一句感受变成可复现的证据。站内 性能与可扩展性 讲过吞吐、延迟与扩展性的关系，压测模型、数据与流量回放 讲过开环与闭环的区别，这里不再重复定义，直接交付一个能跑的服务、一个开环 loadgen，以及三份 profile。判断瓶颈要同时回答三个问题：请求在哪一段排队、CPU 在忙什么、内存分配由谁产生。只拿一张 P99 截图，无法区分“CPU 算不过来”“锁等太久”和“下游本来就慢”。下面的基线故意保留一个真实项目常见的写法：一把全局锁保护订单表，并在持锁期间调用库存、支付、通知三个下游。它不是稻草人，而是许多“先跑通再优化”的服务的真实起点。
基线服务：一把锁串起全部下游
服务只有三个操作：创建、查询、支付。创建与查询走同一张内存订单表；支付在持锁状态下依次调用库存预占、支付扣款、通知。三个下游都用可注入延迟的替身，生产实现换成端口即可。
// file: internal/order/service.go
// tier: L2
// verify: go test ./...
package order
import (
"context"
"encoding/json"
"errors"
"fmt"
"sync"
)
type Status string
const (
StatusCreated Status = "CREATED"
StatusPaid Status = "PAID"
)
type Item struct {
SKU string
Quantity int
UnitPriceCents int64
}
type Order struct {
ID string
CustomerID string
Status Status
Items []Item
TotalCents int64
Version int
}
var (
ErrNotFound = errors.New("order not found")
ErrInvalidState = errors.New("invalid state")
)
type Inventory interface {
Reserve(ctx context.Context, sku string, qty int) error
}
type Payments interface {
Charge(ctx context.Context, orderID string, cents int64) (string, error)
}
type Notifier interface {
Notify(ctx context.Context, orderID string) error
}
// Service 基线：一把全局锁保护订单表，并持锁调用全部下游。
type Service struct {
mu sync.Mutex
seq int
orders map[string]*Order
inventory Inventory
payments Payments
notifier Notifier
}
func NewService(inv Inventory, pay Payments, notify Notifier) *Service {
return &Service{orders: map[string]*Order{}, inventory: inv, payments: pay, notifier: notify}
}
func clone(o *Order) *Order {
b, _ := json.Marshal(o)
var out Order
_ = json.Unmarshal(b, &out)
return &out
}
func (s *Service) Create(_ context.Context, customerID string, items []Item) (*Order, error) {
s.mu.Lock()
defer s.mu.Unlock()
s.seq++
o := &Order{ID: fmt.Sprintf("ord-%06d", s.seq), CustomerID: customerID,
Status: StatusCreated, Items: append([]Item(nil), items...)}
for _, it := range o.Items {
o.TotalCents += int64(it.Quantity) * it.UnitPriceCents
}
s.orders[o.ID] = o
return clone(o), nil
}
func (s *Service) Get(_ context.Context, id string) (*Order, error) {
s.mu.Lock()
defer s.mu.Unlock()
o, ok := s.orders[id]
if !ok {
return nil, ErrNotFound
}
return clone(o), nil
}
// Pay 持锁调用库存、支付、通知；临界区约等于三个下游延迟之和。
func (s *Service) Pay(ctx context.Context, id string) (*Order, error) {
s.mu.Lock()
defer s.mu.Unlock()
o, ok := s.orders[id]
if !ok {
return nil, ErrNotFound
}
if o.Status != StatusCreated {
return nil, ErrInvalidState
}
for _, it := range o.Items {
if err := s.inventory.Reserve(ctx, it.SKU, it.Quantity); err != nil {
return nil, err
}
}
if _, err := s.payments.Charge(ctx, o.ID, o.TotalCents); err != nil {
return nil, err
}
if err := s.notifier.Notify(ctx, o.ID); err != nil {
return nil, err
}
o.Status, o.Version = StatusPaid, o.Version+1
return clone(o), nil
}
Pay 的临界区长度等于三个下游延迟之和。假设库存 2ms、支付 4ms、通知 2ms，那么每笔支付独占全局锁约 8ms；这 8ms 内所有创建和查询都要排队。clone 用 JSON 做深拷贝，是另一个刻意保留的热点：它让读路径产生可被 alloc profile 捕捉的分配，而不是靠猜。
开环 loadgen 与 1ms 桶直方图
压测器按固定间隔发起请求，不等待上一个请求完成。延迟从“计划到达时刻”起算，完成时刻超过 200ms 就记为超时；生成器自身不再设置并发上限，避免把“压测器拒绝”与“服务超时”混为一谈。直方图用 1ms 宽的定长桶，Percentile 返回包含目标样本的桶上限，是近似值。
// file: internal/loadgen/loadgen.go
// tier: L2
// verify: go test ./...
package loadgen
import (
"context"
"math"
"sync"
"time"
)
type Histogram struct {
counts []int64
}
func NewHistogram(maxMS int) *Histogram { return &Histogram{counts: make([]int64, maxMS+1)} }
func (h *Histogram) Observe(d time.Duration) {
if d < 0 {
d = 0
}
h.counts[min(int(d/time.Millisecond), len(h.counts)-1)]++
}
func (h *Histogram) Percentile(q float64) time.Duration {
var total int64
for _, n := range h.counts {
total += n
}
if total == 0 {
return 0
}
target := int64(math.Ceil(min(max(q, 0), 1) * float64(total)))
var seen int64
for i, n := range h.counts {
seen += n
if seen >= target {
return time.Duration(i+1) * time.Millisecond
}
}
return time.Duration(len(h.counts)) * time.Millisecond
}
type Result struct {
Offered, Started, Completed, TimedOut int64
Hist *Histogram
Wall time.Duration
}
type RunOpen struct {
Interval time.Duration
Duration time.Duration
Timeout time.Duration
Task func(context.Context) error
}
func (r *RunOpen) Run() Result {
res := Result{Hist: NewHistogram(2000)}
var wg sync.WaitGroup
var mu sync.Mutex
start := time.Now()
ticker, deadline := time.NewTicker(r.Interval), time.NewTimer(r.Duration)
defer ticker.Stop()
defer deadline.Stop()
loop:
for {
select {
case <-deadline.C:
break loop
case planned := <-ticker.C:
res.Offered++
res.Started++
wg.Add(1)
go func() {
defer wg.Done()
ctx, cancel := context.WithTimeout(context.Background(), r.Timeout)
defer cancel()
err := r.Task(ctx)
elapsed := time.Since(planned)
mu.Lock()
res.Hist.Observe(elapsed)
switch {
case elapsed > r.Timeout:
res.TimedOut++
case err != nil:
res.TimedOut++
default:
res.Completed++
}
mu.Unlock()
}()
}
}
wg.Wait()
res.Wall = time.Since(start)
return res
}
固定负载与数据规模
请求混合比例固定为 40% 创建、35% 查询、25% 支付，用递增序号经过一次乘法混合生成确定性选择；预建 4,000 笔订单作为支付池，避免“重复支付”混入失败统计。负载为 1,500 请求/秒、持续 3 秒、超时 200ms。
// file: internal/loadgen/baseline_test.go
// tier: L2
// verify: go test ./...
package loadgen
import (
"archlab/internal/order"
"context"
"os"
"runtime"
"sync"
"sync/atomic"
"testing"
"time"
)
type downstream struct {
inv, pay, notify time.Duration
mu sync.Mutex
invCalls, payCalls, notifyCalls int
}
func (d *downstream) track(p *int) { d.mu.Lock(); *p++; d.mu.Unlock() }
func sleep(ctx context.Context, dur time.Duration) error {
select {
case <-time.After(dur):
return nil
case <-ctx.Done():
return ctx.Err()
}
}
func (d *downstream) Reserve(ctx context.Context, _ string, _ int) error {
d.track(&d.invCalls)
return sleep(ctx, d.inv)
}
func (d *downstream) Charge(ctx context.Context, _ string, _ int64) (string, error) {
d.track(&d.payCalls)
return "pay-1", sleep(ctx, d.pay)
}
func (d *downstream) Notify(ctx context.Context, _ string) error {
d.track(&d.notifyCalls)
return sleep(ctx, d.notify)
}
// ARCHLAB_BASELINE=1 go test ./internal/loadgen -run TestBaseline -v \
// -cpuprofile cpu.out -memprofile mem.out -mutexprofile mutex.out
func TestBaselineOpenLoop(t *testing.T) {
if os.Getenv("ARCHLAB_BASELINE") == "" {
t.Skip("set ARCHLAB_BASELINE=1 to run the 3s open-loop baseline")
}
runtime.SetMutexProfileFraction(1)
ds := &downstream{inv: 2 * time.Millisecond, pay: 4 * time.Millisecond, notify: 2 * time.Millisecond}
svc := order.NewService(ds, ds, ds)
ctx := context.Background()
items := []order.Item{{SKU: "sku-a", Quantity: 1, UnitPriceCents: 1999}}
ids := make([]string, 0, 4000)
for i := 0; i < 4000; i++ {
o, err := svc.Create(ctx, "cust", items)
if err != nil {
t.Fatal(err)
}
ids = append(ids, o.ID)
}
var seq, paySeq atomic.Int64
mix := func(n uint64) uint64 { return (n*0x9e3779b97f4a7c15 + 0xbf58476d1ce4e5b9) >> 17 }
task := func(ctx context.Context) error {
n := uint64(seq.Add(1))
switch r := mix(n) % 100; {
case r < 40:
_, err := svc.Create(ctx, "cust", items)
return err
case r < 75:
_, err := svc.Get(ctx, ids[mix(n+7)%uint64(len(ids))])
return err
default:
i := paySeq.Add(1) - 1
if i >= int64(len(ids)) {
return nil
}
_, err := svc.Pay(ctx, ids[i])
return err
}
}
run := RunOpen{Interval: time.Second / 1500, Duration: 3 * time.Second, Timeout: 200 * time.Millisecond, Task: task}
res := run.Run()
t.Logf("offered=%d started=%d completed=%d timed_out=%d wall=%s",
res.Offered, res.Started, res.Completed, res.TimedOut, res.Wall.Round(time.Millisecond))
t.Logf("rps_completed=%.2f p50=%s p99=%s p999=%s downstream inventory=%d payment=%d notify=%d",
float64(res.Completed)/res.Wall.Seconds(), res.Hist.Percentile(0.50), res.Hist.Percentile(0.99),
res.Hist.Percentile(0.999), ds.invCalls, ds.payCalls, ds.notifyCalls)
}
真实基线结果
以下输出来自本机 macOS（darwin/arm64，Apple M1 Pro，Go 1.26.0），命令为 ARCHLAB_BASELINE=1 go test ./internal/loadgen -run TestBaselineOpenLoop -count=1 -v -cpuprofile cpu.out -memprofile mem.out -mutexprofile mutex.out，单次运行；原始输出保存在 .local/reports/be-arch/be-arch-perf-12-1-benchmark-baseline-bottleneck-run.txt：
=== RUN TestBaselineOpenLoop
baseline_test.go:85: offered=4110 started=4110 completed=2930 timed_out=1180 wall=3.198s
baseline_test.go:87: rps_completed=916.15 p50=199ms p99=208ms p999=399ms downstream inventory=1028 payment=358 notify=169
--- PASS: TestBaselineOpenLoop (3.21s)
计划到达 4,110 个请求，全部启动，完成 2,930 个，超时 1,180 个。完成吞吐 916.15 请求/秒，只有目标 1,500 的 61.1%。P50 199ms、P99 208ms、P999 399ms：中位数已经贴在 200ms 超时线上，说明大多数请求不是“偶尔慢”，而是普遍在排队。
下游计数比延迟更能说明问题：库存调用 1,028 次，扣款 358 次，通知 169 次。1,028 次支付尝试都拿到了锁并进入库存预占，但只有 358 次在超时前走到扣款，169 次走到通知并标记 PAID；其余 189 次扣款成功后，请求在通知阶段超过 200ms，订单没有落成 PAID。这是长临界区叠加无幂等的直接后果：客户端看到超时，钱可能已经扣了。
Profile 指认瓶颈，而不是猜
三份 profile 的原始输出保存在 .local/reports/be-arch/be-arch-perf-12-1-benchmark-baseline-bottleneck-pprof.txt，用 go tool pprof 读取；下列行与文件逐行一致：
=== Mutex top (delay, cumulative) ===
481.67s 100% 100% 481.67s 100% sync.(*Mutex).Unlock
0 0% 100% 438.04s 90.94% archlab/internal/order.(*Service).Pay
0 0% 100% 25.91s 5.38% archlab/internal/order.(*Service).Get
Duration: 3.21s, Total samples = 300ms ( 9.33%)
100ms 33.33% 33.33% 100ms 33.33% runtime.kevent
2613.76kB 18.09% 18.09% 7222.29kB 49.99% archlab/internal/order.(*Service).Create
2048.31kB 14.18% 32.27% 2048.31kB 14.18% encoding/json.Marshal
1024.14kB 7.09% 68.83% 2560.20kB 17.72% encoding/json.Unmarshal
mutex profile 在 3.2 秒窗口里累计记录 481.67 秒等待，其中 438.04 秒（90.94%）归到 Pay。这不是推理，是运行时采样：锁等待几乎全部由支付路径产生。CPU profile 的总采样只有 300ms，占窗口的 9.33%，最热的是调度与网络轮询，应用自身没有进入前列——CPU 根本没有跑满。alloc profile 中 Create 累计占 49.99%，JSON 编解码是主要来源。
三项证据合起来指向同一个结论：瓶颈是 Pay 持锁调用下游，不是 CPU，也不是内存。修复方向因此明确：缩短临界区、把下游调用移出锁、把通知改为异步、给扣款加幂等键。缓存和限流不能替代这一步；在锁不松开之前加缓存，只会让更多请求排在同一把锁后面。
这份结果只在本机、本次运行成立。开环生成器与服务在同一进程，下游是 time.Sleep 替身，没有真实网络、连接池、TLS 与数据库；绝对吞吐不能当作生产容量。同一台机器上并行跑其他任务时，ticker 会漏拍，offered 在 4,100 到 4,500 之间漂移，正文保留原始值而不做平滑。
可以复用的是方法：固定到达率、固定数据、固定种子、同时记录 offered/started/completed/timed_out，再用 mutex、CPU、alloc 三份 profile 交叉验证。下一节在同一服务上加入缓存、outbox 与令牌桶，并用同一套负载做对照；12.3 再把正常、下游延迟、下游错误三种场景放进同一张表。
常见错误与边界
第一，把 completed 当吞吐。它只统计在超时内完成的请求；排队后超时的请求既占用了服务时间，又没有进入 completed，单看它会高估健康度。第二，只看平均延迟。本机基线的均值被大量快速创建/查询拉低，P50 却已经贴在 200ms 超时线上；尾延迟和超时率才是排队信号。第三，把超时当成“没发生”。扣款调用 358 次、通知 169 次，中间 189 次是已扣款但未落库的订单；没有幂等键时，客户端重试会造成二次扣款。第四，用 CPU 使用率判断瓶颈。本例 CPU 只有 9.33%，如果因此得出“机器还有余量、可以继续加负载”，就会忽略锁等待已经让 1,180 个请求超时。
小结
本节把“服务慢”拆成可验证的三层证据：开环负载下 offered 4,110、completed 2,930、timed_out 1,180，完成吞吐 916.15 请求/秒；mutex profile 显示 481.67 秒等待的 90.94% 来自 Pay；CPU 采样只占窗口的 9.33%，alloc 热点是 JSON 深拷贝。结论不是“加机器”，而是“把下游调用移出全局锁并为扣款建立幂等”。下一节按这个证据链做改造。
阅读导航：上一节：11.3 读写分离的延迟预算与一致性兜底 · 下一节：12.2 缓存、异步与限流改造 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。