34.3 性能分析方法 (火焰图 / pprof / perf)
一句话
性能分析不是「猜哪里慢」,而是固定顺序的三步:先用 USE/RED 定位到资源或服务,再用采样剖析把耗时归因到函数,最后用火焰图确认占比;顺序反了,工具再多也只是生成漂亮图片。
三层定位:先问「哪一层慢」
| 层 | 要回答的问题 | 工具 | 产出 |
|---|---|---|---|
| 症状层 | 哪个 SLI 破了?P99、错误率还是吞吐? | SLO 看板、端到端分段 | 「慢」的具体定义 |
| 资源/服务层 | CPU、内存、磁盘、网络、锁、下游,谁先饱和? | USE、RED、metrics | 可疑资源清单 |
| 代码层 | 哪个函数/哪一行吃掉了时间? | pprof、perf、eBPF、trace | 可改的热点 |
🔑 多数无效 profiling 都发生在「跳过前两层,直接抓火焰图」。CPU 只有 30% 时抓 CPU profile,看到的全是噪声,然后得出「代码没问题」的错误结论。
USE:逐个资源查三件事
USE = Utilization (利用率)、Saturation (饱和度)、Errors (错误)。对每个资源都问这三个问题。
| 资源 | Utilization | Saturation | Errors |
|---|---|---|---|
| CPU | usage%、每核利用率 | runqueue 长度、load average、调度延迟 | 降频、MCE、cgroup throttling |
| 内存 | 已用 / 上限、RSS | page fault、swap in/out、OOM kill | ECC、分配失败 |
| 磁盘 | %util、IOPS / 吞吐 | avgqu-sz、await、写回积压 | IO error、只读重挂 |
| 网络 | 带宽利用率、pps | 重传率、丢包、accept 队列 | CRC、连接重置 |
| 连接池 | 已用 / 最大连接 | 等待队列长度、获取连接耗时 | 获取超时、连接失效 |
| 锁 | 持有时间占比 | 等待线程数、mutex profile | 死锁、饥饿 |
💡 CPU 利用率高不等于 CPU 是瓶颈:如果 runqueue 一直很短,说明只是「忙但没排队」;反过来,CPU 70% 但 runqueue 单调增长,拐点已经到了 (34.1 性能指标)。饱和度比利用率更接近真相。
RED:逐个服务查三件事
RED = Rate (请求速率)、Errors (错误率)、Duration (耗时分布)。USE 看资源,RED 看服务,两者交叉才能定位「是服务本身慢,还是它依赖的资源慢」。
| 指标 | 看什么 | 异常时的第一反应 |
|---|---|---|
| Rate | QPS / 每分钟请求数 | 流量突增?重试放大? |
| Errors | 5xx / 超时 / 业务失败率 | 先看错误类型,不要只看总数 |
| Duration | P50 / P95 / P99 / P999 | P99 涨而 P50 不动 → 长尾/排队;两者都涨 → 整体变慢 |
采样、插桩、追踪:三种观测方式
| 方式 | 原理 | 开销 | 能看到 | 看不到 |
|---|---|---|---|---|
| 采样剖析 (pprof/perf) | 每隔一段时间抓一次调用栈 | 低 (1%–5%) | 统计热点、调用关系 | 少于采样间隔的短事件、精确次数 |
| 插桩 (metrics/log/trace) | 代码里显式计数/打点 | 中–高 | 精确计数、业务语义 | 未打点的代码路径 |
| 分布式追踪 (Trace) | 请求级上下文传播 | 中 (采样后低) | 跨服务因果、每段耗时 | 服务内部函数级细节 |
🔑 采样回答「时间花在哪」,插桩回答「发生了多少次」,追踪回答「慢在哪一段」。定位容量问题先看插桩/追踪,定位代码热点才用采样。
pprof:五种 profile,五个问题
Go 的 pprof 不是「一个工具」,而是五种不同数据源。选错 profile,等于用体温计量血压。
| Profile | 回答的问题 | 采集方式 | 开销 | 关键参数 |
|---|---|---|---|---|
| CPU | on-CPU 时间花在哪些函数 | 默认 100Hz 采样 | 低 (通常 <5%) | seconds=30 |
| Heap | 谁在分配、谁在持有内存 | 每 512KB 分配采样一次 | 低 | alloc_space / inuse_space |
| Goroutine | 现在有多少 goroutine、卡在哪 | 全量快照 | 低 | debug=1 / debug=2 |
| Block | 阻塞在 channel/mutex/select 多久 | 需 SetBlockProfileRate | 中 | blockprofilerate |
| Mutex | 锁竞争多严重、谁持有久 | 需 SetMutexProfileFraction | 中 | mutexprofile |
💡
runtime/trace不是 pprof profile:go tool pprof读不了.trace文件,要用go tool trace打开。它回答的是调度/GC/goroutine 的时序,属于另一条观测通道 (见 15.9 性能剖析工具链 (火焰图 / perf / eBPF))。
一个可复现的 CPU 热点
package ppdemo
import "testing"
var blob = func() []byte {
b := make([]byte, 8<<20) // 8MB 数据
x := uint32(12345)
for i := range b {
x = x*1664525 + 1013904223
b[i] = byte(x >> 24)
}
return b
}()
var hashSink uint64
// Hash 是纯 CPU 热点:逐字节 FNV-1a
func Hash(data []byte) uint64 {
h := uint64(14695981039346656037)
for _, b := range data {
h ^= uint64(b)
h *= 1099511628211
}
return h
}
func BenchmarkHash(b *testing.B) {
for i := 0; i < b.N; i++ {
hashSink = Hash(blob)
}
}
采集与查看:
# 跑 3 秒,产出 CPU profile
go test -bench BenchmarkHash -benchtime 3s -cpuprofile cpu.out
# 文本视图:flat 是本函数耗时,cum 是含子调用
go tool pprof -top -nodecount=8 cpu.out
# 行级归因:时间落在哪一行
go tool pprof -list=Hash cpu.out
# 浏览器里看火焰图/调用图
go tool pprof -http=:8081 cpu.out
本机 (Apple M1) 的真实输出 (重跑会有几个百分点的波动):
BenchmarkHash-8 207 17289848 ns/op
File: ppdemo.test
Type: cpu
Duration: 5.45s, Total samples = 5.04s (92.47%)
flat flat% sum% cum cum%
4.87s 96.63% 96.63% 5s 99.21% ppdemo.Hash (inline)
0.13s 2.58% 99.21% 0.13s 2.58% runtime.asyncPreempt
0 0% 99.21% 5s 99.21% ppdemo.BenchmarkHash
行级视图 (行号来自测试文件):
ROUTINE ======================== ppdemo.Hash
4.87s 5s (flat, cum) 99.21% of Total
. . 18:func Hash(data []byte) uint64 {
. . 19: h := uint64(14695981039346656037)
4.87s 5s 20: for _, b := range data {
. . 21: h ^= uint64(b)
. . 22: h *= 1099511628211
. . 23: }
三个读图要点:
(inline)不是「没数据」:Hash被内联进 benchmark,pprof 仍然把样本归给它。看到(inline)说明编译器认为它值得内联,不是采样失败。flat与cum要分开读:flat高 = 这个函数自己耗 CPU;cum高但flat低 = 时间在子调用里,需要继续往下看。- 行级归因可能整段落在循环行:编译器把
h ^= ...; h *= ...折叠/向量化后,采样只能归到for这一行。这不影响结论,但别指望行级数字精确到语句。
火焰图:宽度是占比,不是时间轴
| 维度 | 含义 | 常见误读 |
|---|---|---|
| x 轴 | 样本的聚合,宽度 = 该栈占全部样本的比例 | 当成时间线,以为左边先发生 |
| y 轴 | 调用栈深度,越往下越接近根 | 以为越高越慢;高度只是栈深 |
| 颜色 | 通常按包/模块着色,无语义 | 以为红色代表慢 |
| 顶部 | 叶子函数 (on-CPU 时是真正在跑的函数) | 只看顶部忽略调用链 |
自顶向下 vs 自底向上
| 视图 | 根在哪 | 展开方向 | 适合回答 |
|---|---|---|---|
| 火焰图 (flame graph) | 底部 | 向上展开被调用者,顶部是叶子 | 「这个入口下面都干了什么」 |
| 冰柱图 (icicle) | 顶部 | 向下展开被调用者 | 同上,方向相反,读起来更顺 |
| 反向/自底向上 (reverse) | 叶子在底部 | 向上展开调用者 | 「这个热点是被谁调起来的」 |
💡 不同工具对「火焰图」的朝向实现不同:Brendan Gregg 的
flamegraph.pl根在底部,Go pprof 的 Web 视图根在顶部 (本质是冰柱图)。看根节点的名字确认方向,不要背朝向。排查「某个函数为什么被调用」用 bottom-up,排查「这个接口的时间花在哪」用 top-down;pprof 的-peek就是按调用者/被调用者展开。
五种典型形状,五种结论
| 形状 | 说明 | 下一步 |
|---|---|---|
| 宽平顶:单个函数占 60% 以上 | CPU-bound 热点 | 换算法、减少调用次数、向量化/批处理 |
| 多个中等宽度:序列化、日志、metrics 各占 10%–20% | 固定开销分散 | 减少调用次数、采样日志、异步上报 |
| 高瘦塔:深递归/层层框架 | 栈开销、反射、拦截器 | 剪枝、去反射、合并中间层 |
顶部是 runtime.mallocgc / GC | 分配压力,不是计算 | 看 heap profile:对象池、预分配、减少逃逸 |
| 中间断层/大片 unknown | 在等 IO、锁、调度,或符号缺失 | off-CPU/block/mutex profile、perf、补符号 |
on-CPU 与 off-CPU
CPU profile 只统计「在 CPU 上跑」的样本。一个请求 90% 时间在等数据库,CPU 火焰图会扁得看不出热点——这不是没问题,而是问题不在 CPU。
| 视角 | 回答 | 工具 |
|---|---|---|
| on-CPU | 谁在消耗 CPU | pprof CPU、perf record |
| off-CPU | 谁在等待、等多久、被谁唤醒 | pprof block、perf sched、eBPF offcputime |
| 调度 | 谁在等 CPU、等多久 | perf sched、runqlat |
差异火焰图:优化到底有没有用
# 优化前
go tool pprof -proto -output before.pb.gz http://svc:6060/debug/pprof/profile?seconds=30
# 优化后 (同样负载、同样时长)
go tool pprof -proto -output after.pb.gz http://svc:6060/debug/pprof/profile?seconds=30
# 红色 = after 变多 (回归),蓝色 = after 变少 (改善)
go tool pprof -diff_base=before.pb.gz -http=:8081 after.pb.gz
⚠️ 差异图必须同负载、同采样时长、同机器。两次流量不同,差异图只会告诉你「流量变了」,不会告诉你「代码变快了」。
perf 与 eBPF:pprof 看不到的那一半
Go 的 pprof 只懂 Go 进程;系统调用、内核态、调度、页缓存、TCP 重传要靠 perf/eBPF。
| 命令 | 回答 | 典型用途 |
|---|---|---|
perf stat -p <pid> sleep 10 | IPC、cache miss、上下文切换、page fault | 判断是「算得慢」还是「内存/调度拖累」 |
perf top -p <pid> -g | 实时热点 (含内核符号) | 快速看内核态占比 |
perf record -F 99 --call-graph dwarf -p <pid> -- sleep 30 | 采样调用栈 | 生成火焰图 (perf script \| flamegraph.pl) |
perf sched record -- sleep 10 后 perf sched latency | 调度延迟、谁被饿死 | 线程多但 CPU 没满时 |
perf c2c record/report | 缓存行伪共享 | 多核扩展性差、原子操作慢 |
bpftrace -e '...' | 任意内核/用户态事件 | IO 延迟分布、off-CPU 时间、TCP 重传 |
几条常用的 eBPF 命令 (bcc/bpftrace 工具集):
# 块设备 IO 延迟直方图 (毫秒)
biolatency -m 10
# 指定进程的 off-CPU 时间分布,采样 10 秒
offcputime -p <pid> 10
# 调度延迟 (等 CPU 的时间) 分布
runqlat 10
容器里的三个前提:
| 前提 | 检查 | 不满足时 |
|---|---|---|
| 权限 | perf_event_paranoid ≤ 2,或 CAP_PERFMON / CAP_SYS_ADMIN | perf 报 permission denied |
| 内核符号 | /proc/kallsyms 可读、kernel.kptr_restrict=0 | 内核栈全是地址 |
| 栈回溯 | 有 frame pointer 或 debug info | --call-graph dwarf 开销大、栈缺失 |
💡 生产环境优先用 eBPF:开销可控、不需要重启、能按 PID/cgroup 过滤。
perf适合一次性深挖,不适合 7×24 常开。
从「慢」到「改哪一行」:固定流程
① 定义慢:哪个 SLI、哪个接口、哪段时间、哪个分片
② 分段:客户端 → 网关 → 服务 → 下游,找到耗时所在段
③ 资源:USE 查该段涉及的 CPU/内存/IO/锁/池
④ 选 profile:CPU 高 → CPU;CPU 低 → block/off-CPU;内存涨 → heap
⑤ 采样:≥30s,多窗口,记录版本/负载/机器
⑥ 归因:flat/cum → 函数 → 行;火焰图确认占比
⑦ 改一处:只改一个变量,保留 before/after profile
⑧ 复测:同负载对比差异图 + 端到端 P99
症状 → 首选工具 → 常见根因
| 症状 | 首选工具 | 常见根因 |
|---|---|---|
| CPU 100%,QPS 上不去 | CPU profile | 热点函数、GC、锁自旋、正则回溯 |
| CPU 30%,延迟高 | block / off-CPU / trace | 等 DB、等锁、等网络、线程池排队 |
| 内存缓慢上涨 | heap inuse_space + goroutine | 泄漏 (全局 map、未关闭的 body、goroutine 堆积) |
| 周期性 P99 尖刺 | trace + GC 日志 + perf sched | GC、定时任务、缓存集中失效、日志轮转 |
| 单机慢、其他正常 | perf stat + 邻居监控 | CPU 降频、超线程争抢、NUMA、磁盘坏盘 |
| 压测 QPS 上不去,服务端很闲 | 客户端监控 + USE | 发压机端口耗尽、连接池太小、TLS 握手 |
| 只有大请求慢 | 按 payload 分桶 + CPU/heap | 序列化、拷贝、大对象分配、O(n²) |
连续剖析:把 profile 变成指标
一次性 profile 只能回答「当时为什么慢」。连续剖析 (continuous profiling) 每分钟采 10 秒,把样本按版本/实例聚合,就能回答「哪个版本引入了回归」。
| 维度 | 一次性 profile | 连续剖析 |
|---|---|---|
| 采样 | 出问题时手动抓 | 7×24 自动,10s/分钟 |
| 开销 | 可接受 | 1%–3% CPU、少量存储 |
| 用途 | 定位当前热点 | 版本对比、回归告警、容量趋势 |
| 工具 | go tool pprof | Pyroscope、Grafana Profiles、Parca |
与 50.8 持续性能剖析 的分工:本节讲「怎么读」,50.8 讲「怎么在产品里落地、怎么控制成本」。没有基线时,连续剖析的最大价值是让你知道「上周这个函数只占 5%,这周占了 40%」。
反模式
| 反模式 | 后果 |
|---|---|
| 不看资源直接抓 CPU profile | CPU 不忙时全是噪声,得出「代码没问题」 |
| 只采样 5 秒 | 样本太少,热点随机跳动;周期性任务完全采不到 |
| 只看 flat 不看 cum | 漏掉「自身不耗时但调用链巨大」的框架层 |
把 (inline) 当缺失符号 | 误判工具坏了,重复折腾 |
| 没有 before/after 就宣称优化 | 无法区分代码收益和流量波动 |
| 用开发机 profile 推断生产 | CPU 型号、核数、GC 压力、数据量全不同 |
| 生产开 CPU profile 忘了关 | 持续写文件、增加开销;同一进程同时只能有一个 CPU profile,重复开启会失败 |
| 只优化火焰图最宽的那一块 | 最宽的不一定是瓶颈 (可能不在关键路径) |
| 用微基准代替端到端 | 微基准里的函数被内联/常量折叠,线上不是这样跑 |
| 忽略 GC/分配,只看计算 | 分配压力把 CPU 吃在 mallocgc/GC 上,优化算法没用 |
自检
Q1 CPU 火焰图最宽的一块是 runtime.mallocgc,其次是 GC。这说明什么?下一步看哪个 profile?
▸ 答案:说明瓶颈是分配压力,不是业务计算。每次请求分配了大量临时对象,CPU 花在分配和回收上。下一步看 heap profile 的 alloc_space (谁分配最多) 和 inuse_space (谁持有最多),再结合逃逸分析找「本可以栈上分配却逃逸到堆」的对象;优化手段是对象池、预分配、减少字符串/JSON 中间对象,而不是继续优化算法。
Q2 某服务 P99 从 200ms 涨到 2s,但 CPU 只有 25%,CPU profile 几乎是平的。你应该看什么?
▸ 答案:先确认「等待」发生在哪:① block profile 看 channel/mutex/select 阻塞;② off-CPU/eBPF 看 IO、锁、调度;③ 分布式 trace 看是 DB、下游 RPC 还是本服务排队;④ USE 查连接池等待队列、下游延迟、磁盘 await。CPU 低 + 延迟高,典型原因是排队 (池太小、下游慢、锁竞争),继续抓 CPU profile 不会有结论。
Q3 你优化了一个函数,CPU profile 显示它从 40% 降到 10%,但接口 P99 没变。可能的原因是什么?
▸ 答案:① 该函数不在关键路径上,或者只占端到端延迟的一小部分 (端到端还包括网络、排队、下游);② 优化后瓶颈转移到了别的资源 (Amdahl / USL);③ 火焰图占比是「CPU 时间占比」,不是「请求延迟占比」,多核并行下 CPU 降了但关键路径没变;④ 测量的是不同负载/不同版本。正确做法是用端到端 P99 + 分段耗时验证,而不是只看 profile 占比。
Q4 两个版本的 CPU profile 怎么比较才可信?为什么不能直接看「热点函数占比」?
▸ 答案:用差异火焰图 (-diff_base),并保证同机器、同负载、同采样时长、同请求分布;比较的是「同一函数在两次采样中的样本数差值」,而不是绝对占比——总样本数会随 CPU 使用率变化,占比会被其他函数稀释。还要注意采样噪声:样本量小的时候,±5% 的差异不显著,至少采样 30 秒并对多实例聚合。
Q5 为什么 perf 在容器里经常「什么都看不到」?给出三个检查点。
▸ 答案:① 权限:perf_event_paranoid 太大或缺 CAP_PERFMON/CAP_SYS_ADMIN,perf_event_open 被拒绝;② 符号:内核 kptr_restrict、容器没挂 /proc/kallsyms、二进制被 strip,栈只有地址;③ 栈回溯:没有 frame pointer 或 debug info,--call-graph fp 拿不到完整栈,dwarf 又需要额外空间/开销。三者缺一,火焰图就会出现大量 unknown 或断层。