简单介绍 pprof 工具中 goroutine 以及 heap 工具
写在前面
在进行 go 项目开发过程中,精度要求比较高的情况下,需要对 go 的运行时进行分析。go 语言原生默认提供了 ip:host/debug/pprof
工具,通过分析其提供的数据可以一定程度了解运行时状态。
比如通过分析运行时状态,可以了解资源泄露情况、探究代码中的死锁情况等。
本文将提供几个小例子的分析,用来帮助大家熟悉 pprof/goroutine
和 pprof/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 行的十六进制 0x102e7df23
、0x43
以及十进制 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/goroutine
和 pprof/heap
进行初步的排查(看看有没有协程泄露?有没有内存泄露?)。
小结
本文简单介绍了 go 语言中原生的 net/http/pprof
包的使用,并研究了 pprof 中 goroutine 和 heap 统计数据。通过源码层面的分析,读者若能举一反三应该很容易理解 pprof 中提供的其他内容,在工程中遇到疑难杂症时不妨在 pprof 中找找答案。
参考
- go源码 - printStackRecord 打印 goroutine 内容的方法
- go源码 - writeHeapInternal 打印 heap 内容的方法