简单介绍 pprof 工具中 goroutine 以及 heap 工具

写在前面

在进行 go 项目开发过程中,精度要求比较高的情况下,需要对 go 的运行时进行分析。go 语言原生默认提供了 ip:host/debug/pprof 工具,通过分析其提供的数据可以一定程度了解运行时状态。

比如通过分析运行时状态,可以了解资源泄露情况、探究代码中的死锁情况等。

本文将提供几个小例子的分析,用来帮助大家熟悉 pprof/goroutinepprof/heap 的指标。

正文

在工程中加入 pprof 监控

比如下面的工程,在 web 项目中引入 _ "net/http/pprof" 即可(由于 pprof 是通过 web 接口暴露出去的,因此项目必须启动一个 web 服务才可以)。

import (
	"io"
	"math/rand"
	"net/http"
	_ "net/http/pprof"
	"strconv"
	"time"
)

func main() {

	helloHandler := func(w http.ResponseWriter, req *http.Request) {
		no := rand.Int63n(1 << 56)
		noStr := strconv.Itoa(int(no))
		io.WriteString(w, "Hello, "+noStr)
		time.Sleep(time.Minute) // 查看多个协程的存在
	}
	http.HandleFunc("/hello", helloHandler)
	http.ListenAndServe("localhost:8848", nil)
}

上面的代码启动后,即可通过多次 curl localhost:8848/hello 创建多个 goroutine,从而方便查看 pprof/goroutine 中的内容。

一个 pprof/goroutine 的例子

goroutine profile: total 7
2 @ 0x102e51e90 0x102e4b668 0x102e7df24 0x102f56b94 0x102f56c24 0x102f57c18 0x102fed624 0x102ffcbcc 0x1030ec474 0x102e83ab4
#	0x102e7df23	internal/poll.runtime_pollWait+0x43		/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/netpoll.go:343
#	0x102f56b93	internal/poll.(*pollDesc).wait+0x83		/opt/homebrew/Cellar/go/1.21.1/libexec/src/internal/poll/fd_poll_runtime.go:84
#	0x102f56c23	internal/poll.(*pollDesc).waitRead+0x33		/opt/homebrew/Cellar/go/1.21.1/libexec/src/internal/poll/fd_poll_runtime.go:89
#	0x102f57c17	internal/poll.(*FD).Read+0x307			/opt/homebrew/Cellar/go/1.21.1/libexec/src/internal/poll/fd_unix.go:164
#	0x102fed623	net.(*netFD).Read+0x53				/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/fd_posix.go:55
#	0x102ffcbcb	net.(*conn).Read+0x6b				/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/net.go:179
#	0x1030ec473	net/http.(*connReader).backgroundRead+0x73	/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/server.go:683

2 @ 0x102e51e90 0x102e80648 0x1031618dc 0x1030f5cd4 0x1030f80a0 0x1030f9270 0x1030f4fec 0x102e83ab4
#	0x102e80647	time.Sleep+0x107			/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/time.go:195
#	0x1031618db	main.main.func1+0xbb			/Users/chenman/developer/golang/hello/pprof/main.go:18
#	0x1030f5cd3	net/http.HandlerFunc.ServeHTTP+0x43	/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/server.go:2136
#	0x1030f809f	net/http.(*ServeMux).ServeHTTP+0x15f	/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/server.go:2514
#	0x1030f926f	net/http.serverHandler.ServeHTTP+0x29f	/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/server.go:2938
#	0x1030f4feb	net/http.(*conn).serve+0x155b		/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/server.go:2009
... (其他的隐掉)

上面的内容表示当前总共有 7 个 goroutine, 其中有 2 个 goroutine 的在执行 poll.runtime_pollWait 方法,同时有 2 个 goroutine 在执行 time.Sleep 方法。

具体可以参考 printStackRecord 方法,下面我们详细讨论几个细节。

各个数字的含义

在上面的内容中,存在比较多的数字,比如第 2 行的十六进制数组 0x102e51e90 0x102e4b668 0x102e7df24 0x102f56b94 0x102f56c24 0x102f57c18 0x102fed624 0x102ffcbcc 0x1030ec474 0x102e83ab4, 比如第 3 行的十六进制 0x102e7df230x43以及十进制 343 等等。

根据源码分析,其中第 2 行的十六进制数组表示的是当前 goroutine 堆栈栈帧的 PC 列表,也就是在监控拉取的瞬间,总共有 2 个栈帧地址为 0x102e51e90 0x102e4b668 ... 0x1030ec474 0x102e83ab4 的 goroutine;这个数值列表目前笔者尚未使用过,看起来只是 pprof 用来做统计使用的。

第 3 行的十六进制 0x102e7df23 对应的是堆栈栈帧的 PC 值,和第 2 行中的 0x102e7df24 相差 1,之所以会相差 1 好像是个历史问题,目前应该不需要深究。而第 3 行中的 0x43 目前笔者也未曾使用过,这个值是 PC 和 栈帧入口 Entry 的差值。最后十进制 343 表示的是源码 src/runtime/netpoll.go 的第 343 行。

简单总结一下,pprof/goroutine 中十六进制表示运行时栈帧的状态,十进制表示的是源码中对应的行数。

在实践中,我们可以通过 pprof/goroutine 了解项目运行时的状态,比如上面的内容表示有 2 个 goroutine 卡在 time.Sleep,即 demo 源码的第 18 行(当然,这里是我们刻意为之,工程实践中是我们需要关注可能存在优化空间的点)。笔者实际项目中经常通过 pprof/goroutine 寻找业务逻辑中的死锁,屡试不爽的体验😄。

一个 pprof/heap 的例子

heap profile: 1: 704 [1: 705] @ heap/1048576
1: 704 [1: 704] @ 0x102e239f4 0x102e2382c 0x103103db0 0x10310185c 0x102e5e6c4 0x102e5e5a8 0x102e519d4 0x102e83ab4
#	0x103103daf	net/http.map.init.0+0x2f	/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/h2_bundle.go:1189
#	0x10310185b	net/http.init+0x3ab		/opt/homebrew/Cellar/go/1.21.1/libexec/src/net/http/h2_bundle.go:1189
#	0x102e5e6c3	runtime.doInit1+0xd3		/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:6740
#	0x102e5e5a7	runtime.doInit+0x37		/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:6707
#	0x102e519d3	runtime.main+0x1e3		/opt/homebrew/Cellar/go/1.21.1/libexec/src/runtime/proc.go:249

上面第 1 行的内容表示当前有 1 个使用用的对象(活跃的对象),占用了 704 个字节。中括号[1: 705]中的数字表示历史上总共分配过 1 个对象,总共分配了 705 个字节。最后 1048576 表示平均每分配 1048576 个字节进行一次内存分配的采样,这也意味着对象相关的所有数据都是采样获得到的,仅保证统计意义上的准确性,具体数值会存在一些波动。 第 2 行的内容表示运行时堆栈 0x102e239f4 0x102e2382c 0x103103db0 0x10310185c 0x102e5e6c4 0x102e5e5a8 0x102e519d4 0x102e83ab4 表示的过程当前有 1 个活跃的对象,占用 704 字节;中括号中的数字历史上总共分配了 1 个对象,总共约 705 个字节。

如果项目中存在明显的内存泄露,可以结合 pprof/goroutinepprof/heap 进行初步的排查(看看有没有协程泄露?有没有内存泄露?)。

小结

本文简单介绍了 go 语言中原生的 net/http/pprof 包的使用,并研究了 pprof 中 goroutine 和 heap 统计数据。通过源码层面的分析,读者若能举一反三应该很容易理解 pprof 中提供的其他内容,在工程中遇到疑难杂症时不妨在 pprof 中找找答案。

参考