jimyag's Blog

用 pprof 和 Delve 排查 Go 程序

· 4213 字 · 约 17 分钟

Markdown

最后更新:

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

在复现负载时采一份 CPU profile

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

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

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 方法的路由模式。打开三个终端：第一个运行服务，第二个持续发请求，第三个采集。尽量让采集窗口覆盖负载；在程序空闲时抓到一份 CPU profile，回答不了慢请求在做什么。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

# 终端 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 和 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，先去掉旧根路径，再到本机的源码目录查找：

1
2

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 用户指南 还有调用图和差异分析的用法。

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

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

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

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

1
2
3

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、runtime.SetMutexProfileFraction，只打开 HTTP 路由不会开始收集这两类数据。可用参数和各 profile 的含义见 net/http/pprof 与 runtime/pprof.Profile。

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

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

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

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)
	}
}

1
2
3
4

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：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

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()
}

1
2
3
4
5

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 的建议分开采集。

用 execution trace 区分排队和执行

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

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

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

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
	}
}

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

1
2
3
4
5
6

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 文档。

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

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

1
2

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 提示符输入：

1
2

break main.digest
continue

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

1
2
3
4
5
6

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 放在一起。测试用不同的轮数调用同一函数：

1
2
3
4
5
6
7
8
9

package main

import "testing"

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

1
2

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 提示符下：

1
2
3
4
5

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

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

示例使用 Go 1.27.3、macOS arm64 和 Delve 1.27.2。若使用其他 Go 版本，选择支持该版本的 Delve；命令含义见 Delve CLI 文档。

构建和测试参数见 go build、go test 测试选项与 Go 编译器命令行。

#Go

相关文章