一个 Go 接口变慢时，先区分两个问题：一段时间里程序大多在做什么，以及某次请求为什么走到这条分支。pprof 用采样或运行时统计回答第一个问题；Delve 在本地复现中停住一次执行，让你看调用栈和变量。用下面这个本地服务，可以把两种工具串起来。

<!--more-->

## 在复现负载时采一份 CPU profile

将下面的程序保存为 `main.go`。诊断路由只监听本机；在真实服务里，建议把它们放在受访问控制的管理端口上，避免跟业务路由一起对外开放。

```go
package main

import (
	"crypto/sha256"
	"fmt"
	"log"
	"net/http"
	"net/http/pprof"
)

func digest(rounds int) [32]byte {
	sum := sha256.Sum256([]byte("profile demo"))
	for range rounds {
		sum = sha256.Sum256(sum[:])
	}
	return sum
}

func main() {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /work", func(w http.ResponseWriter, _ *http.Request) {
		fmt.Fprintf(w, "%x\n", digest(100000))
	})
	mux.HandleFunc("GET /debug/pprof/", pprof.Index)
	mux.HandleFunc("GET /debug/pprof/profile", pprof.Profile)
	log.Fatal(http.ListenAndServe("127.0.0.1:6060", mux))
}
```

这里用到 Go 1.22 起支持的 [带 HTTP 方法的路由模式](https://pkg.go.dev/net/http#ServeMux)。打开三个终端：第一个运行服务，第二个持续发请求，第三个采集。尽量让采集窗口覆盖负载；在程序空闲时抓到一份 CPU profile，回答不了慢请求在做什么。

```sh
# 终端 1
go build -o app main.go
./app

# 终端 2，采完后按 Ctrl+C
while curl -fsS -o /dev/null http://127.0.0.1:6060/work; do :; done

# 终端 3
curl -fsS -o cpu.pprof 'http://127.0.0.1:6060/debug/pprof/profile?seconds=5'
go tool pprof -top ./app cpu.pprof
go tool pprof -list='main.digest' ./app cpu.pprof
```

这些命令的参数分别是，括号中的英文用于助记：

- `go build -o app`（output，输出）：把编译得到的程序命名为 `app`。
- `curl -fsS`：合写 `-f`（fail，HTTP 失败状态时返回错误）、`-s`（silent，隐藏进度）和 `-S`（show error，静默时仍显示错误）。循环会在 curl 失败时停止。
- `curl -o ...` / `--output`：指定响应正文的输出文件；`/dev/null` 表示丢弃正文，`cpu.pprof` 则保留采样数据。
- `seconds=5`：URL 查询参数，要求 pprof 接口采集 5 秒 CPU 数据；它不是 curl 的选项。
- `pprof -top`（top entries）：按采样量列出函数。
- `pprof -list='main.digest'`（list，列出）：按正则表达式选择函数，显示带采样标注的源码行。
- `./app cpu.pprof`：前者是用于解析符号的二进制，后者是采样文件。

`-top` 按采样量列函数。CPU profile 里的 `flat` 是样本落在函数自身的时间估计，`cum` 还包含经它调用的下层函数。以这个程序为例，一次实测中，`main.digest` 自身只有约 40 ms 的样本，但累计约 950 ms，其中约 910 ms 来自循环调用 `sha256.Sum256` 的那行。只看 `flat` 会低估这段循环的代价；`-list` 把样本映射到源码行，正好能找到这次调用。

这是采样估计，五秒内的总样本量不是接口请求耗时，也不要求恰好等于五秒；并行执行可以累计多个线程的 CPU 时间。保留采集时使用的二进制版本，源码列表也要用同一版源码。对不方便开 HTTP 的本地测试，同类数据可以用 `go test -run '^$' -bench . -cpuprofile cpu.pprof` 采集（前提是包里有基准），或者在程序中调用 [`runtime/pprof.StartCPUProfile`](https://pkg.go.dev/runtime/pprof#StartCPUProfile) 和 `StopCPUProfile`。

- `-run '^$'`（run，运行）：只运行名称匹配正则表达式的普通测试；`^$` 匹配空名称，因此跳过普通测试。
- `-bench .`（benchmark，基准）：运行名称匹配 `.` 的基准，也就是全部基准。
- `-cpuprofile cpu.pprof`（CPU profile）：把测试运行期间的 CPU 采样写入指定文件。

### 用浏览器看调用图，或在另一台机器看源码

`go tool pprof -http : ./app cpu.pprof` 会在本机启动 Web 界面。省略主机和端口时，默认用 `localhost` 和一个可用端口；访问终端打印的地址即可。加 `-no_browser` 可以禁止自动打开浏览器。交互命令行也能查同一份数据：先运行 `go tool pprof ./app cpu.pprof`，再输入 `top` 或 `list main.digest`。

- `-http :`：启用 HTTP 界面，`:` 两侧分别省略主机名和端口，使用上述默认值。
- `-no_browser`（no browser）：保留 Web 服务，但不自动打开浏览器。

二进制和 profile 从构建机拷到本机后，`top` 可能能读出函数名，`list` 却找不到源文件。例如记录的路径是 `/build/work/app/main.go`，同版本源码在本机的 `$PWD/source/main.go`，先去掉旧根路径，再到本机的源码目录查找：

```sh
go tool pprof -list='main.digest' \
  -trim_path=/build/work/app -source_path="$PWD/source" ./app cpu.pprof
```

- `-trim_path`（trim path，裁去路径）：去掉 profile 记录的旧路径前缀。
- `-source_path`（source path，源码路径）：指定本机查找源码的起点。
- `-help`（help，帮助）：列出本机版本支持的参数。

这些选项不会改变原始采样，也不能修复源码版本不一致的问题。我把示例源码移到另一个目录，按这两个路径参数重新列出了带样本的行。[pprof 用户指南](https://github.com/google/pprof/blob/main/doc/README.md) 还有调用图和差异分析的用法。

## 内存上涨和等待过长要换 profile

CPU profile 解释 CPU 在哪里工作，不能直接解释在 channel 或锁上等了多久。先根据现象挑数据：

| 现象 | 看什么 | 怎么读 |
| --- | --- | --- |
| 堆长期上涨 | `heap` 的 `inuse_space` | 看采样时仍存活的堆分配来自哪里；同等负载下对照两次结果，单次大分配不等于泄漏。 |
| GC 很频繁，堆大小却稳定 | `allocs` 的 `alloc_space` | 看历史累计分配量，包含已经释放的分配；用同等窗口或前后差值看持续分配热点。 |
| goroutine 越来越多 | `goroutine` | 看当前 goroutine 的调用栈；多次抓取，比较是不是同一批等待位置持续增加。 |
| 同步等待长、锁竞争多 | `block` 或 `mutex` | `block` 看同步原语上的阻塞位置；`mutex` 看造成竞争的互斥锁持有方释放锁时的调用栈。先用运行时采样开关开启，调完再关闭。 |

在上述示例还运行时，可以试着采集堆和 goroutine：

```sh
curl -fsS -o heap.pprof 'http://127.0.0.1:6060/debug/pprof/heap?gc=1'
go tool pprof -top -inuse_space ./app heap.pprof
curl -fsS 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=2'
```

- `gc=1`（garbage collection，垃圾回收）：在采集堆数据前触发 GC，诊断时也要考虑这一额外开销。
- `-inuse_space`（in-use space，仍在使用的空间）：选择采样时仍存活的堆分配字节数。
- `debug=2`：让 goroutine 接口返回详细的文本调用栈，而不是默认的二进制 profile。

`block`、`mutex` 需要分别设置 [`runtime.SetBlockProfileRate`](https://pkg.go.dev/runtime#SetBlockProfileRate)、[`runtime.SetMutexProfileFraction`](https://pkg.go.dev/runtime#SetMutexProfileFraction)，只打开 HTTP 路由不会开始收集这两类数据。可用参数和各 profile 的含义见 [`net/http/pprof`](https://pkg.go.dev/net/http/pprof) 与 [`runtime/pprof.Profile`](https://pkg.go.dev/runtime/pprof#Profile)。

### 同一份堆数据，两种相反的热点

一个服务经常分配临时缓冲区，另一个地方却一直持有一份缓存。只看“谁分配最多”，很容易以为应该先删临时缓冲区才能解决堆持续增长。下面用同一份 profile 区分两类开销。另建一个目录，把程序保存为 `heap.go`：

```go
package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
)

var retained, scratch []byte

func retain() {
	retained = make([]byte, 4<<20)
}

func churn() {
	for range 32 {
		scratch = make([]byte, 1<<20)
	}
	scratch = nil
}

func main() {
	runtime.MemProfileRate = 1 // 仅为实验提高采集精度；不要把这个值直接用于线上。
	retain()
	churn()
	runtime.GC()

	f, err := os.Create("heap.pprof")
	if err != nil {
		log.Fatal(err)
	}
	if err := pprof.WriteHeapProfile(f); err != nil {
		_ = f.Close()
		log.Fatal(err)
	}
	if err := f.Close(); err != nil {
		log.Fatal(err)
	}
}
```

```sh
go build -o heap-demo heap.go
./heap-demo
go tool pprof -top -alloc_space ./heap-demo heap.pprof
go tool pprof -top -inuse_space ./heap-demo heap.pprof
```

- `-alloc_space`（allocated space，已分配空间）：选择历史累计分配字节数，包含后来已释放的分配。
- `-inuse_space`：选择仍存活的分配字节数；这两个选项只改变报告读取的样本列，不重新采集。

在 `alloc_space` 里，`main.churn` 有约 32 MiB 的累计分配；切到 `inuse_space` 后，`main.retain` 仍保留约 4 MiB，`churn` 的临时缓冲区不再占大头。两份报告用的是同一文件，只是选了不同的样本列。`churn` 是减少分配与 GC 工作的线索，`retain` 才是检查对象为什么还被引用的起点。堆 profile 记录的是分配调用栈，不能直接回答现在是谁持有引用，也不能与进程的 RSS 画等号。生产排查时在相近负载下取两份快照，看 `inuse_space` 是否随时间持续增加。

### 同一把锁，等待方和持有方分别在哪里

下面的测试只制造一类已知竞争：四个 goroutine 轮流持有同一把锁，锁内故意等待一小段时间。它不测试吞吐，用来让两种 profile 的归因区别显现出来。另存为 `lock_test.go`：

```go
package main

import (
	"sync"
	"testing"
	"time"
)

func guarded(mu *sync.Mutex) {
	mu.Lock()
	time.Sleep(2 * time.Millisecond)
	mu.Unlock()
}

func TestContention(t *testing.T) {
	var mu sync.Mutex
	var wg sync.WaitGroup
	for range 4 {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for range 5 {
				guarded(&mu)
			}
		}()
	}
	wg.Wait()
}
```

```sh
go test -count=1 -run '^TestContention$' -o lock.test \
  -blockprofile=block.pprof -blockprofilerate=1 \
  -mutexprofile=mutex.pprof -mutexprofilefraction=1 lock_test.go
go tool pprof -top ./lock.test block.pprof
go tool pprof -top ./lock.test mutex.pprof
```

这次 `go test` 的参数是：

- `-count=1`（count，次数）：运行一次，并显式禁用测试结果缓存，确保本次实际执行。
- `-run '^TestContention$'`：只选择这个名称的测试，`^` 和 `$` 分别锚定名称的开头和结尾。
- `-o lock.test`（output）：保留名为 `lock.test` 的测试二进制，供后续解析符号。
- `-blockprofile=block.pprof`：输出同步阻塞 profile。
- `-blockprofilerate=1`（rate，采样率）：记录每次阻塞事件；一般取值表示平均每阻塞多少纳秒采样一次。
- `-mutexprofile=mutex.pprof`：输出互斥锁竞争 profile。
- `-mutexprofilefraction=1`（fraction，采样比例）：记录每次锁竞争事件；设为 N 时平均采样约 1/N。

看 `block.pprof` 时，找到 `sync.(*Mutex).Lock` 及它的上层 `guarded`，这里的栈属于想拿锁却等住的 goroutine；报告也可能列出测试框架和 `WaitGroup.Wait`。看 `mutex.pprof` 时，`sync.(*Mutex).Unlock` 的栈指向释放锁的一方。本次测试这两条栈分别累计约 119 ms 和 120 ms，数值会随调度变化。多个 goroutine 同时等同一把锁时，等待时间可以累加，可能比测试本身的经过时间还大。修复时先回到持锁路径，确认锁保护的是哪些数据，以及耗时动作是否真的要在临界区里做。不同诊断工具也会互相影响；需要量化线上开销时按 [Go Diagnostics](https://go.dev/doc/diagnostics#profiling) 的建议分开采集。

## 用 execution trace 区分排队和执行

如果想知道 goroutine 已经可以运行，为什么还迟迟没有执行，CPU profile 只能说明采样时 CPU 在执行谁。Go 的 [execution trace](https://pkg.go.dev/runtime/trace) 会记录 goroutine 阻塞、变为可运行以及开始运行的事件，可以在时间线上区分两段等待：等 channel 等条件满足，以及条件满足后等调度器分配执行机会。调度器里的 G、M、P 关系可对照[《Goroutine 调度器的 GMP 模型的设计思想》](/posts/goroutinegmp-goroutine-gmp-go/)。

把下列测试保存为 `trace_test.go`，与上文的 `main.go` 放在一起。测试创建四个 goroutine 后才关闭 `start`，允许它们开始计算。`GOMAXPROCS=1` 限制同一时刻只有一个 P 执行 Go 代码，便于观察排队。

```go
package main

import "testing"

func TestDigestScheduler(_ *testing.T) {
	const workers = 4
	start := make(chan struct{})
	results := make(chan [32]byte, workers)
	for range workers {
		go func() {
			<-start
			results <- digest(500000)
		}()
	}
	close(start)
	for range workers {
		<-results
	}
}
```

同一测试分两次采集，避免两种诊断工具互相干扰：

```sh
GOMAXPROCS=1 go test -count=1 -run '^TestDigestScheduler$' -cpuprofile=cpu-test.pprof -o cpu-test.test main.go trace_test.go
go tool pprof -top ./cpu-test.test cpu-test.pprof

GOMAXPROCS=1 go test -count=1 -run '^TestDigestScheduler$' -trace=trace.out -o sched-test.test main.go trace_test.go
go tool trace -pprof=sched trace.out > sched.pprof
go tool pprof -top ./sched-test.test sched.pprof
```

- `GOMAXPROCS=1`：只为该命令设置 Go 运行时的并行度上限；这是环境变量，不是 `go test` 参数。
- `-trace=trace.out`（trace，跟踪）：把运行时事件写到指定文件。
- `go tool trace -pprof=sched`（scheduler，调度器）：把 trace 转成调度延迟的 pprof 格式，写到标准输出。
- `> sched.pprof`：shell 的输出重定向，将转换结果保存到文件。

Go 1.27.3 实测，第一份报告的类型为 `cpu`，主要样本落在哈希计算；第二份类型为 `delay`，按调用栈汇总已经可运行、但还没运行的调度延迟。后者虽然也是 pprof 能打开的格式，但不能当成 CPU 时间或 channel 阻塞时间。trace 的事件里还能看到一个计算中的 goroutine 被抢占、回到可运行状态，随后另一个 goroutine 开始执行。要看这类先后关系，可以用 `go tool trace trace.out` 打开时间线；`sched.pprof` 的汇总结果不保留顺序。命令和其他 trace 报告类型见 [`go tool trace` 文档](https://pkg.go.dev/cmd/trace)。

## 用 Delve 看一次请求的调用现场

如果 pprof 已把范围缩小到 `digest`，而你想确认一次请求实际传了多少轮、从哪个处理函数调用它，可以在本地调试。先停止前面的服务，再构建一个关闭优化和内联的副本，避免局部变量被优化掉或源码行与指令难以对应。这个副本只用于调试，不用它替代前面的二进制做性能对比。

```sh
go build -gcflags='all=-N -l' -o debug-app main.go
dlv exec ./debug-app
```

- `-gcflags='all=-N -l'`（Go compiler flags，Go 编译器选项）：把引号内的选项传给编译器；`all=` 表示作用于所有参与构建的包。
- 编译器的 `-N`：关闭优化。
- 编译器的 `-l`：关闭内联（inlining）。
- `dlv exec`（execute，执行）：启动并调试已经构建好的二进制。

在 Delve 提示符输入：

```text
break main.digest
continue
```

另开终端运行 `curl -fsS http://127.0.0.1:6060/work`，请求会在断点处暂停。回到 Delve：

```text
args
stack
next
next
print sum
continue
```

`args` 会显示 `rounds = 100000`；`stack` 可看到 `main.digest` 的上一层是路由处理函数。在这次运行中，第一次 `next` 停在初始化 `sum` 的语句，第二次停在循环行；此时赋值才执行完，`print sum` 能读到哈希状态。再 `continue` 让请求完成。涉及协程时可以用 `goroutines` 列出 goroutine，`goroutine <id>` 切换后再查 `stack`。结束时按 Ctrl+C 暂停，再用 `quit` 退出。断点会扰动服务进程的执行，宜在调试副本上复现。

### 同一函数被反复调用，只停在想看的输入

如果函数同时服务普通和慢路径，每次调用都停会让定位更难。把下面的测试保存为 `digest_cases_test.go`，与最开始的 `main.go` 放在一起。测试用不同的轮数调用同一函数：

```go
package main

import "testing"

func TestDigestCases(t *testing.T) {
	if digest(10) == digest(100000) {
		t.Fatal("different round counts produced the same digest")
	}
}
```

```sh
go test -c -gcflags='all=-N -l' -o debug-case.test main.go digest_cases_test.go
dlv exec ./debug-case.test -- -test.run '^TestDigestCases$'
```

- `go test -c`（compile，编译）：只生成测试二进制，不运行测试。
- `--`：结束 Delve 自己的选项，后面的参数交给被调试的程序。
- `-test.run '^TestDigestCases$'`：由测试二进制只运行指定测试；直接运行测试二进制时需要 `test.` 前缀。

在 Delve 提示符下：

```text
break slow main.digest if rounds == 100000
continue
args
clear slow
continue
```

实测第一次 `digest(10)` 正常执行，断点只在第二次调用满足条件时停住，`args` 显示 `rounds = 100000`；清掉断点并继续后，测试通过。这里没有修改业务函数，也不需要向测试服务连续发请求。条件表达式应选当前栈帧里可检查的局部量；不要为了判断条件去执行会改变状态的代码。更多写法见 [Delve 条件断点](https://github.com/go-delve/delve/blob/v1.27.2/Documentation/cli/cond.md)。

示例使用 Go 1.27.3、macOS arm64 和 Delve 1.27.2。若使用其他 Go 版本，选择支持该版本的 Delve；命令含义见 [Delve CLI 文档](https://github.com/go-delve/delve/blob/v1.27.2/Documentation/cli/README.md)。

构建和测试参数见 [`go build`](https://pkg.go.dev/cmd/go#hdr-Compile_packages_and_dependencies)、[`go test` 测试选项](https://pkg.go.dev/cmd/go#hdr-Testing_flags)与 [Go 编译器命令行](https://pkg.go.dev/cmd/compile#hdr-Command_Line)。