时间到底花在哪里: 请求延迟 = On-CPU + Off-CPU — 指标找方向, 链路找段, 画像找行, 分析就是把这本时间账单拆清楚
性能分析像医院分诊: P99 报警是"病人发烧", 它只告诉你有问题, 不告诉你病因; 你要按 指标 → 链路 → 画像 三层漏斗逐层缩小, 先分清是"整体变慢"还是"长尾拖垮", 再分清是"在算"(On-CPU) 还是"在等"(Off-CPU)。所有性能问题最终都归到一本时间账单: 这 200ms 里, CPU 算了多久, 等锁多久, 等 DB 多久, 在队列里排了多久 — 高手和新手的差距, 就是能不能把这本账拆清楚, 而不是"看到 CPU 高就加机器"。
lat = [10]*99 + [10000] # 99 个 10ms + 1 个 10s mean = sum(lat)/len(lat) # → 109.9ms 平均"看起来还行" p99 = sorted(lat)[98] # → 10ms P99 也看不见它 max = max(lat) # → 10000ms 只有 Max 暴露真相
# P50↑ P95↑ P99↑ → 整体变慢: 容量 / 依赖变慢 / 发布回归 # P50 平 P99↑ → 长尾: 锁竞争 / 缓存miss / GC / 重传 # P99 平 Max↑ → 极端异常: 单实例故障 / 个别超大请求
# QPS = 10000, P99 = 10s → 吞吐亮眼, 系统半死 # 健康判断三件套: 吞吐 + 延迟分位数 + 错误率, 缺一不可
L = 1000 * 0.1 # 1000 QPS × 100ms → 常态并发 100 L = 1000 * 2.0 # 延迟恶化到 2s → 并发 2000, 池子打满
$ vmstat 1 # r=40 b=0 us=80 wa=0 → 8核 runnable=40: CPU 饱和排队 # r=2 b=25 us=10 wa=70 → b=25: 进程在等 IO, 磁盘饱和
# Rate: rate(http_requests_total[5m]) # Errors: sum(rate(http_requests_total{code=~"5.."}[5m])) / rate(...) # Duration: histogram_quantile(0.99, rate(..._bucket[5m]))
# CPU: util=1-idle sat=vmstat r err=dmesg mce # Disk: util=%util sat=aqu-sz err=/proc/diskstats # Net: util=带宽 sat=retrans/drop err=errors
# 集群平均 CPU 50%: # pod-A 100% ← 冒烟 pod-B 30% pod-C 20% # 正解: sum by (instance) (...) 拆开看 + max_over_time 兜底
p_ok = 0.99 # 单个下游 P99 达标 all = p_ok ** 20 # 扇出 20 个 → 整体 P99 达标率 0.818
total, json_pct = 100, 1 # DB 占 90, JSON 占 1 new = 100 - 1 + 1/10 # → 99.1ms: JSON 快 10 倍也白搭
# W = s/(1-ρ), s=20ms: # ρ=0.50 → 40ms ρ=0.70 → 67ms ρ=0.85 → 133ms ρ=0.95 → 400ms
# On-CPU: perf record -F 99 -p PID -g -- sleep 30 # Off-CPU: offcputime-bpfcc -p PID 30 (线程没在 CPU 上时在等谁)
# Grafana: P99 4s ↑ → Metrics: 哪里出问题 # Trace: db.query span 3.8s → Trace: 哪一段出问题 # pprof: sqlkit.Scan 40% → Profile: 哪一行代码
告警只说明 P99 越线。先画 P50/P95/P99/Max 四条线对齐时间线, 再按 instance 拆, 5 分钟内把问题空间从"全系统"缩到一句话。
# 1) 分位数全景 (Prometheus): 四条线放同一张图 histogram_quantile(0.99, sum by (le) (rate(http_request_duration_seconds_bucket[5m]))) histogram_quantile(0.50, sum by (le) (rate(http_request_duration_seconds_bucket[5m]))) # 2) 变更对齐: 出事时间点附近有没有 deploy / 配置变更 ls -lt /opt/app/releases | head -3 sar -q -f /var/log/sa/sa26 # 历史负载, 对齐 10:00 deploy → 10:02 P99↑ # 3) 按 instance 拆: 只有一台高 → 单实例故障, 不是容量问题 topk(3, sum by (instance) (rate(http_requests_total[5m])))
分诊结论决定方向: 整体变慢查依赖与容量; 长尾查锁/GC/重传; 单实例查热点与倾斜。
池子按"常态并发"设计是事故源: 延迟恶化 8 倍时并发也涨 8 倍, 池子瞬间打满。容量设计必须用"恶化后的并发"。
QPS, lat = 800, 0.15 inflight = QPS * lat # 120 → 常态并发 pool = int(inflight * 1.5) # 180 → 池留 50% 余量 # 压测/事故推演: 依赖变慢 lat=0.8s 时 inflight = QPS * 0.8 # 640 → 必须能扛 640 并发 # 若池只有 180: 剩 460 个请求在池口排队 → wait 时间↑ → 超时 → 重试 # 结论: 池子是 backpressure 阀门, 宁可排队拒绝, 不可无限放大
上线后持续监控 pool.wait_count / wait_duration, 等待时间上涨比连接满更危险。
没有 RED 指标, 一切分诊都是空谈。一个中间件同时产出 Rate / Errors / Duration, 之后所有告警与画像都从这里来。
var reqDur = prometheus.NewHistogramVec(prometheus.HistogramOpts{ Name: "http_request_duration_seconds", Buckets: []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10}, }, []string{"route", "code"}) func wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() d := &statusRecorder{ResponseWriter: w, code: 200} next.ServeHTTP(d, r) reqDur.WithLabelValues(r.URL.Path, strconv.Itoa(d.code)). Observe(time.Since(start).Seconds()) // Duration + (code→Errors) 一次埋好 }) }
bucket 必须覆盖 SLO 边界 (如 P99 目标 200ms 就要有 0.2 桶), 否则分位数算不准。
把 USE 固化成巡检配置, 值班同学照单执行, 不靠记忆。每行一个资源, 三列分别是利用率、饱和度、错误的取数方法。
# perf-checklist.yaml — 值班巡检 / 事故 first-5-min checks: cpu: {util: "1 - mpstat idle", sat: "vmstat r > 2*cores", err: "dmesg mce"} memory: {util: "free available", sat: "si/so 持续活跃", err: "dmesg oom"} disk: {util: "iostat %util", sat: "aqu-sz 持续 > 1", err: "io error"} net: {util: "sar -n DEV 带宽", sat: "retrans/drops 增长", err: "carrier errors"} pool: {util: "active/max", sat: "wait_count 增长", err: "acquire timeout"}
巡检口径统一后, "CPU 80% 正不正常"这类争论变成查表: 看 sat 列, r 队列堆积才是真饱和。
"JSON 慢所以要换 protubuf"是拍脑袋。先采 CPU profile 看 flat 占比, 占比小的段优化十倍也是白干。
# 30 秒 CPU 画像, 看 flat 占比 go tool pprof -top http://svc:6060/debug/pprof/profile?seconds=30 # flat flat% sum% cum% # 12.3s 45.2% 45.2% encoding/json.Marshal ← 大头, 优先 # 0.8s 3.1% 48.3% strings.Builder ← 先放放 # 同理 Python: py-spy top --pid 1234 看热点函数占比
把每段 cum% 记进优化清单按占比排序, 优化 45% 的段收益是 3% 段的 15 倍。
告警线为什么是 70~80% 而不是 95%? 因为延迟随利用率指数起飞, 95% 时 P99 已经爆炸, 扩容来不及了。
def mm1_latency(util, s): # M/M/1 排队模型: W = s / (1 - ρ), ρ=utilization, s=服务时间 return s / (1 - util) s = 0.02 # 单请求服务时间 20ms for u in (0.5, 0.7, 0.85, 0.95): print(u, round(mm1_latency(u, s)*1000), "ms") # 0.5 → 40ms 0.7 → 67ms 0.85 → 133ms 0.95 → 400ms # 结论: 85% 后延迟非线性起飞 → 告警/扩容线定 70~80%
把这条曲线贴进容量评审文档, 从此"CPU 90% 要不要扩"有了数学答案。
CPU 15%、P99 5s 的服务, On-CPU profile 一无所获 — 因为时间都在等。切换 Off-CPU 画像, 等待点直接现形。
# 第一步: syscall 统计, 看线程在等什么 strace -c -p 1234 -o /tmp/st.txt && head -8 /tmp/st.txt # futex 3800 92.1% ← 92% 时间在等锁 # 第二步: off-CPU 画像, 按等待对象聚合 offcputime-bpfcc -p 1234 30 > /tmp/off.txt # jdbc.Pool.Acquire 2800ms ← 等连接池 # sync.Mutex.Lock 900ms ← 等全局锁
排查链: CPU 低 → 先想"在等" → strace/futex 验证 → offcputime 定位等待对象 → 代码修复。
"用户说慢"到"哪一段慢"之间隔着一个 Trace。关键路径分段埋 span, 2 秒去哪了一目了然。
ctx, span := tracer.Start(ctx, "GET /orders") defer span.End() _, auth := tracer.Start(ctx, "auth") // 10ms _, dbq := tracer.Start(ctx, "db.orders") // 100ms _, rpc := tracer.Start(ctx, "rpc.price") // 1.85s ← 元凶 _, ser := tracer.Start(ctx, "serialize") // 20ms // Jaeger 里一眼看到: 2s 中 1.85s 在 rpc.price // 下一步去 price 服务的 RED/USE, 继续往下钻
span 命名用资源动作规范 (db.orders / rpc.price), 跨团队才能对得上。
集群平均 P99 200ms 时 pod-3 已经 5s。平均值把事故藏到"总体还行"里, 告警必须按实例检查。
# prometheus-rules.yaml - alert: InstanceP99High expr: | histogram_quantile(0.99, sum by (instance, le) (rate(http_request_duration_seconds_bucket[5m]))) > 1 for: 5m labels: {severity: page} # 配套: max_over_time(cpu{mode="idle"}[5m]) 找冒烟实例
同类地, CPU/内存/连接池告警全部加 by (instance), 热点与倾斜才藏不住。
事故头 5 分钟最值钱。把"现象→范围→机器层→变更"固化成脚本, 值班照跑, 输出直接贴事故频道。
#!/bin/bash # triage.sh — 事故分诊前 6 问 echo "== Q1/Q2 哪个服务, 哪个 endpoint 慢 (从告警拿) ==" echo "== Q3 P50 还是 P99: 分位数四条线 ==" curl -s "http://prom:9090/api/v1/query?query=histogram_quantile(0.99,sum by (le)(rate(http_request_duration_seconds_bucket[5m])))" echo "== Q4/Q5 所有实例还是部分 / 机器层总览 ==" uptime; vmstat 1 3; iostat -xz 1 3 echo "== Q6 最近发布/变更 ==" ls -lt /opt/app/releases | head -3
禁止事项写进脚本注释: 先别重启、先别扩容、先别改配置 — 那是在销毁证据。
P50/P95/P99 + Max 四件套。 # 错: avg = sum(lat)/len(lat) # → 109.9ms, 10s 被抹平 # 对: p99 = quantile(lat, 0.99); mx = max(lat)
# 错: report(qps=10000) # "扛住了" # 对: report(qps, p99, err_rate) # 三件套齐全
vmstat r / aqu-sz / pool wait。 # 错: cpu=80% → scale_out() # 白花钱 # 对: sat = run_queue > 2*cores 判断后再扩
# 错: "P50 20ms, 很稳" # P99 已 2s # 对: dashboard: p50/p95/p99/max 四条线
# 错: L = 1000 * 100 # → 100000 (把 ms 当 s) # 对: L = 1000 * 0.1 # → 100 并发
pprof -top 看占比排序再动手。 # 错: 优化 strings.Builder (3%) # 收益≈0 # 对: 优化 json.Marshal (45%) # 收益最大
by (instance)。 # 错: avg(cpu) 全局一条线 # 对: cpu by (instance) + max_over_time 兜底
# 错: alert: cpu > 0.95 # 对: alert: cpu > 0.75 and run_queue > cores
sar / pprof / dmesg) 再处置。 # 错: systemctl restart app # 证据没了 # 对: curl :6060/debug/pprof/heap > heap.pb.gz 再重启
tail sampling 保 errors/慢请求/稀有路由。 # 错: sampler: always_on # 对: tail_sampling: [error=100%, latency>1s, default 1%]
offcputime / strace -c / block profile。 # 错: 只跑 perf record # 看不出"在等" # 对: offcputime-bpfcc -p PID 30
allocs profile)。 # 错: "调大 GOGC" 收工 # 下一波又爆 # 对: go tool pprof allocs → json.Decode 65%
# 错: Buckets: [0.1, 1, 10] # 对: Buckets: [.005,.01,.025,.05,.1,.25,.5,1,2.5,5,10]
# 错: rate(http_requests_total[1m]) # 对: rate(http_requests_total[5m]) + for: 5m
# 错: http.Get(url) # 默认无 deadline # 对: client{Timeout: 2s} + ctx deadline 传递
# 错: wrk -t4 -c100 只看 Requests/sec # 对: 加 --latency 看 p99, 配合服务端指标
# 错: 收到响应才发下一个 (closed-loop) # 对: 固定速率发压 + 记录"应发未发"的延迟
_seconds 一边 _ms, P99 面板差 1000 倍. 原因: 没有命名规范. 正解: 全司统一 _seconds (Prom 约定)。 # 错: api_latency_ms 与 api_latency_seconds 并存 # 对: 统一 *_seconds, 展示层再转 ms
# 错: "10:00~10:20 系统慢" # 对: 10:00 deploy → 10:02 payload↑ → 10:03 CPU↑ → 10:05 P99↑
# 错: "接口偶尔慢" # 无归属 # 对: auth 5ms / db 80ms / rpc 1.85s 逐段可查