本节把 TaskHub 推进到「慢因可见」：上一节的压测告诉你服务在 c=50 到达拐点，但没说拐点来自哪。我们挂上 pprof，用 CPU、heap、mutex 三份 profile 加一份执行 trace，把"慢在哪一行"从猜测变成证据。
适用版本：Go 1.27（实测go1.27.0）。go tool pprof/go tool trace均为工具链自带。
12.2 pprof/trace 定位瓶颈
性能问题的排查顺序是固定的：压测发现"慢" → profile 定位"哪慢" → 改代码 → 再压测验证。上一节做完了第一步，这一节做第二步。核心工具就两个，都是标准库/工具链自带、零第三方依赖：
- pprof：采样，回答"CPU 花在哪些函数、内存谁在占、锁争用多严重"。
- trace：全量事件记录，回答"goroutine 什么时候在等、调度器忙不忙"。
一句话区分：pprof 看"热点"，trace 看"时间线"。热点问题用 pprof，延迟毛刺、调度问题用 trace。
12.2.1 一行导入，挂上观测端点
net/http/pprof 的价值全在 init() 里，空白导入即可：
import (
"log"
"net/http"
_ "net/http/pprof" // 只为触发 init 注册
)
func main() {
log.Fatal(http.ListenAndServe("127.0.0.1:6060", nil)) // nil = 默认 mux
}
注册出来的端点：
| 端点 | 内容 |
|---|---|
/debug/pprof/profile?seconds=5 | CPU profile，采样 5 秒 |
/debug/pprof/heap | 堆分配与存活对象 |
/debug/pprof/goroutine | 所有 goroutine 栈 |
/debug/pprof/mutex | 互斥锁争用 |
/debug/pprof/trace?seconds=2 | 执行 trace |
mutex 和 block 默认不采样，要先打开：
runtime.SetMutexProfileFraction(1) // 1 = 全采样，生产用 100 之类
runtime.SetBlockProfileRate(1)
12.2.2 造一个"有病的"服务
要定位瓶颈，先得有瓶颈。写一个故意犯两种错的 handler：
var (
mu sync.Mutex
shared = map[string]int{}
)
// 热点 1：大量小对象分配 + 哈希
func hotAlloc(n int) int {
total := 0
for i := 0; i < n; i++ {
b := sha256.Sum256([]byte(fmt.Sprintf("task-%d", i)))
total += int(b[0])
}
return total
}
// 热点 2：锁竞争
func hotMutex(n int) {
for i := 0; i < n; i++ {
mu.Lock()
shared[fmt.Sprintf("k-%d", i%64)]++
mu.Unlock()
}
}
/alloc 打 hotAlloc（分配密集），/mutex 起 8 个 goroutine 打 hotMutex（锁竞争）。然后一边压一边抓 profile。
12.2.3 CPU profile：一眼看出锁竞争
抓 5 秒 CPU profile 再 -top：
curl -s -o cpu.prof "http://127.0.0.1:18094/debug/pprof/profile?seconds=5"
go tool pprof -top -nodecount=8 ./pprofdemo cpu.prof
本机实测输出：
File: pprofdemo
Type: cpu
Duration: 5.11s, Total samples = 11s (215.20%)
Showing nodes accounting for 10.11s, 91.91% of 11s total
flat flat% sum% cum cum%
5.20s 47.27% 47.27% 5.20s 47.27% runtime.usleep
2.79s 25.36% 72.64% 2.79s 25.36% runtime.pthread_cond_wait
1.55s 14.09% 86.73% 1.55s 14.09% runtime.pthread_cond_signal
0.18s 1.64% 88.36% 2.16s 19.64% internal/sync.(*Mutex).lockSlow
0.12s 1.09% 89.45% 0.12s 1.09% runtime.madvise
0.12s 1.09% 90.55% 0.12s 1.09% runtime.nanotime1
前几行是 runtime.usleep、pthread_cond_wait——这些是运行时空转，不是业务代码。真正的线索在 internal/sync.(*Mutex).lockSlow：锁竞争慢路径，cum 占了 19.64%。
但 -top 的默认排序（按 flat）会淹没业务函数。用 -focus 直接问"我的函数花了多少"：
go tool pprof -top -cum -nodecount=6 -focus='hotMutex' ./pprofdemo cpu.prof
Showing nodes accounting for 0.09s, 0.82% of 11s total
flat flat% sum% cum cum%
0.02s 0.18% 0.18% 5.62s 51.09% main.hotMutex
0 0% 0.18% 5.62s 51.09% main.main.func2.1
0.05s 0.45% 0.64% 3.85s 35.00% runtime.lock2
0 0% 0.64% 0.82s ... internal/sync.(*Mutex).Unlock (inline)
main.hotMutex 的 cum 是 5.62s，占 51.09%——一半的 CPU 时间耗在这个函数里，而且它自己的 flat 只有 0.02s，说明时间全花在被调用的 runtime.lock2（抢锁）上。这不是计算瓶颈，是锁竞争瓶颈。一眼就能定性。
12.2.4 同样的手法看分配：heap profile
/alloc 那个函数 CPU 上看起来不慢，它的病在内存。抓 heap profile，按 alloc_space（累计分配量）排序：
curl -s -o heap.prof "http://127.0.0.1:18094/debug/pprof/heap"
go tool pprof -top -nodecount=6 -sample_index=alloc_space ./pprofdemo heap.prof
Showing top 6 nodes out of 17
flat flat% sum% cum cum%
238.50MB 79.50% 79.50% 242MB 80.67% fmt.Sprintf
53MB 17.67% 97.16% 133MB 44.33% main.hotAlloc
3MB 1.00% 98.16% 3MB 1.00% fmt.init.func1
结论清清楚楚：fmt.Sprintf 吃掉了 79.5% 的分配量。代码里 fmt.Sprintf("task-%d", i) 每轮调一次，20 万次调用就是 20 万个临时字符串。优化方向直接指向它——用 strconv.Itoa 或 strings.Builder 替掉 fmt.Sprintf。
用 -focus='hotAlloc' 反向确认它 CPU 占用极低：
Showing nodes accounting for 0, 0% of 11000ms total
flat flat% sum% cum cum%
0 0% 0% 110ms 1.00% main.hotAlloc
CPU 只占 1%，却占了 80% 的分配。这就是为什么 12.1 强调"先看 allocs/op"——一个 CPU profile 完全正常的服务，可能在内存和 GC 上烧掉大量资源。
12.2.5 mutex profile：把争用数出来
-focus 能看出"有竞争"，但竞争有多严重？抓 mutex profile，按 contentions（争用次数）看：
curl -s -o mutex.prof "http://127.0.0.1:18094/debug/pprof/mutex"
go tool pprof -top -nodecount=6 -sample_index=contentions ./pprofdemo mutex.prof
Showing top 6 nodes out of 16
flat flat% sum% cum cum%
3879142 71.65% 71.65% 4433889 81.90% sync.(*Mutex).Unlock
1533732 28.33% 100% 1533732 28.33% runtime.unlock (inline)
0 0% 100% 448968 8.29% internal/sync.(*Mutex).lockSlow
387 万次解锁争用（contentions 单位是次数，不是时间）。一个全局 sync.Mutex 保护一个 map，8 个 goroutine 疯狂抢，每次都有人要等。这不是"有点慢"，是"锁设计有根本问题"。
12.2.6 执行 trace：看调度与等待
pprof 是采样，trace 是全量事件。从服务上抓一段执行 trace：
curl -s -o trace.out "http://127.0.0.1:18094/debug/pprof/trace?seconds=2"
trace 文件可以用浏览器打开交互分析，也可以用命令行转成 pprof 格式。工具支持四种视角：
go tool trace -pprof=sync trace.out > sync.pprof # 同步阻塞
go tool trace -pprof=sched trace.out > sched.pprof # 调度延迟
go tool trace -pprof=net trace.out > net.pprof # 网络阻塞
go tool trace -pprof=syscall trace.out > syscall.pprof
本机 -pprof=sync 的结果：
flat flat% sum% cum cum%
2907.21ms 43.40% 43.40% 2907.21ms 43.40% runtime.chanrecv1
2000.27ms 29.86% 73.26% 2000.27ms 29.86% runtime.selectgo
1107.34ms 16.53% 89.79% 1107.34ms 16.53% sync.(*Mutex).Lock
682.21ms 10.18% 100% 682.21ms 10.18% sync.(*WaitGroup).Wait
0 0% 100% 1107.34ms 16.53% main.hotMutex
chanrecv1 和 selectgo 是 HTTP server 在等新连接（空闲等待，正常）；sync.(*Mutex).Lock 的 1107ms 挂在 main.hotMutex 下，和 CPU profile 的结论互相印证。
-pprof=sched（调度延迟）更能说明问题：
flat flat% sum% cum cum%
1.59s 99.81% 99.81% 1.59s 99.81% sync.(*Mutex).Unlock
0 0% 99.81% 1.59s 99.82% main.hotMutex
99.81% 的调度延迟来自 sync.(*Mutex).Unlock。这意味着大量 goroutine 因为抢不到锁被从 CPU 上换下来（调度器介入），不是简单地在原地自旋。这种问题 pprof 只能看出"热"，trace 才能看出"goroutine 被调度器挪来挪去"的代价。
12.2.7 修它：分片锁
定位到"全局锁竞争"，修法就明确了。经典的分片锁（sharded lock）：把一个锁拆成 N 个，按 key 哈希路由到不同分片，竞争面从 1 个缩到 N 个：
var (
shardCount = 64
shards [64]struct {
mu sync.Mutex
m map[string]int
}
)
func incSharded(key string) {
s := &shards[fnv(key)%uint32(shardCount)]
s.mu.Lock()
s.m[key]++
s.mu.Unlock()
}
func fnv(s string) uint32 {
var h uint32 = 2166136261
for i := 0; i < len(s); i++ {
h ^= uint32(s[i])
h *= 16777619
}
return h
}
用并行基准对比全局锁与分片锁（-benchtime=1s）：
BenchmarkMutexGlobal-10 8224465 147.3 ns/op 0 B/op 0 allocs/op
BenchmarkMutexSharded-10 21061714 54.42 ns/op 0 B/op 0 allocs/op
147.3 ns/op → 54.42 ns/op，快 2.7 倍。分片数的选择是个取舍：分片越多竞争越小，但内存占用和"遍历全部数据"的成本越高（分片后要遍历 64 个 map 才能拿到全量）。64 分片是个常见起点，要按实际 key 数量和访问模式调。
sync.Map 是另一个选项，但它适合读多写少且 key 集合稳定的场景；本例是高频写、且 key 分散在多个分片上，分片锁更合适。没有万能方案，要用基准验证。
12.2.8 安全红线：pprof 绝不能暴露公网
pprof 端点是信息泄露的重灾区：heap 里可能有内存中的明文密钥，goroutine 会吐出完整调用栈，cmdline 泄露启动参数，profile 还能被用来做 CPU 耗尽攻击。
正确做法：
- 业务端口和观测端口分开。业务用自定义 mux，pprof 用默认 mux 起在另一个端口。
- 观测端口只绑
127.0.0.1或内网，通过 SSH 隧道访问：
// 业务端口
go func() { _ = http.ListenAndServe(":8080", businessMux) }()
// 观测端口，只绑本机
_ = http.ListenAndServe("127.0.0.1:6060", nil)
生产环境更规范的做法是给观测端口加一层鉴权，或者只在需要排查时临时开、用完就关。
小结
- pprof 看热点，trace 看时间线；
net/http/pprof空白导入即注册端点。 - CPU profile 用
-focus+-cum直接问业务函数花了多少；本机实测hotMutex占 51% CPU，病根是runtime.lock2。 - heap profile 按
alloc_space看，实测fmt.Sprintf占 79.5% 分配；一个 CPU 只占 1% 的函数可能是内存大户。 - mutex profile 的
contentions给出争用次数（实测 387 万次）；go tool trace -pprof=sched显示 99.81% 调度延迟来自锁。 - 分片锁把基准从 147.3ns 优化到 54.42ns（2.7 倍）；
sync.Map不是万能替代。 - pprof 端点必须绑本机或内网，绝不能裸奔在公网。
定位到瓶颈、优化完之后，还有一个维度没碰：内存和 GC。就算 CPU 热点都消掉了，如果堆一直在涨、GC 一直在跑，延迟毛刺照样让你难受。下一节专门讲内存与 GC 调优。
阅读导航：上一节：12.1 基准与压测 · 下一节：12.3 内存与 GC 调优 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。