这是我参与「第五届青训营 」伴学笔记创作活动的第 4 天
今天学习的内容为Go语言性能调优 pprof
性能调优的几大原则
- 依靠数据不是猜测, 大胆假设, 小心求证. 在性能问题定位阶段可以根据假设定位问题, 而优化阶段需要建立完整的度量机制, 来量化性能优化的效果.
- 要定位最大瓶颈而不是细枝末节, 现实世界的代码不是完美的, 它面临着许多取舍, 性能优化也是如此, 在有限的时间/经历下, 最大程度的优化性能, 就需要我们直接对最大瓶颈下手.
- 不要过早优化
- 不要过度优化,
这里我想补充mask的第一性原理
- 约束和限制需求，识别那些真正的需求。
- 尽量删除多余的部分。如果你没有把自己删除的10%又找回来，那么就是删除的不够。
- 优化结构使其变得合理。
- 聚焦提高效率和效益。
- 固化流程和机制，实现自动化。 这五个步骤在系统优化领域同样适用, 在我们日常工作的系统中, 保证系统的高内聚低耦合, 同时高度自动化, 这样才能在系统性能劣化前提前定位, 解决问题.
接下来以 go-pprof-practice 项目, 实战pprof的用法
首先clone下来项目, 并直接运行. 随后访问 http://localhost:6060/debug/pprof/, 可以看到pprof的web统计主页, 具体有以下一些指标
| 类型 | 描述 |
|---|---|
| allocs | 内存分配情况的采样信息 |
| blocks | 阻塞操作情况的采样信息 |
| cmdline | 显示程序启动命令及参数 |
| goroutine | 当前所有协程的堆栈信息 |
| heap | 堆上内存使用情况的采样信息 |
| mutex | 锁争用情况的采样信息 |
| profile | CPU 占用情况的采样信息 |
| threadcreate | 系统线程创建情况的采样信息 |
| trace | 程序运行跟踪信息 |
我们借助go自带的go tool pprof命令排查问题, 它会读取pprof通过web暴露的数据来分析上述指标.
cpu过高
go tool pprof http://localhost:6060/debug/pprof/profile
该命令会读取数据, 然后进入可交互终端
gitpod /workspace/go-pprof-practice (master) $ go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /home/gitpod/pprof/pprof.main.samples.cpu.001.pb.gz
File: main
Type: cpu
Time: Jan 18, 2023 at 9:22am (UTC)
Duration: 30s, Total samples = 17.26s (57.53%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
输入top命令, 显示占用cpu时间最高的函数调用(flat为在该函数中语句的执行, sum为总的执行耗时, 包含函数调用)
(pprof) top
Showing nodes accounting for 17.21s, 99.71% of 17.26s total
Dropped 10 nodes (cum <= 0.09s)
flat flat% sum% cum cum%
17.21s 99.71% 99.71% 17.24s 99.88% github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat
0 0% 99.71% 17.24s 99.88% github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live
0 0% 99.71% 17.25s 99.94% main.main
0 0% 99.71% 17.25s 99.94% runtime.main
输入 list Eat, 可以查看函数具体信息
输入web, 会生成一个svg形式的函数调用耗时的树形图
内存过高
再次输入命令, 后缀改为heap `go tool pprof http://localhost:6060/debug/pprof/heap
再次使用top, list命令
gitpod /workspace/go-pprof-practice (master) $ go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /home/gitpod/pprof/pprof.main.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: main
Type: inuse_space
Time: Jan 18, 2023 at 9:41am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 768MB, 99.74% of 770MB total
Dropped 17 nodes (cum <= 3.85MB)
flat flat% sum% cum cum%
768MB 99.74% 99.74% 768MB 99.74% github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
0 0% 99.74% 768MB 99.74% github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
0 0% 99.74% 768MB 99.74% main.main
0 0% 99.74% 768MB 99.74% runtime.main
(pprof) list Steal
Total: 770MB
ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal in /workspace/go-pprof-practice/animal/muridae/mouse/mouse.go
768MB 768MB (flat, cum) 99.74% of Total
. . 45:
. . 46:func (m *Mouse) Steal() {
. . 47: log.Println(m.Name(), "steal")
. . 48: max := constant.Gi
. . 49: for len(m.buffer)*constant.Mi < max {
768MB 768MB 50: m.buffer = append(m.buffer, [constant.Mi]byte{})
. . 51: }
. . 52:}
可以看到 Steal 函数中向buffer中加入了1G内存.
频繁内存gc
通过 GODEBUG=gctrace=1 ./go-pprof-practice | grep gc, 运行程序, 开启gctrace选项.
等待程序运行一段时间后, 再运行 go tool pprof http://localhost:6060/debug/pprof/allocs, 查看allocs选项.
(pprof) top
Showing nodes accounting for 336MB, 99.70% of 337MB total
Dropped 13 nodes (cum <= 1.69MB)
flat flat% sum% cum cum%
336MB 99.70% 99.70% 336MB 99.70% github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)
0 0% 99.70% 336MB 99.70% github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Live
0 0% 99.70% 336MB 99.70% main.main
0 0% 99.70% 336MB 99.70% runtime.main
(pprof) list Run
Total: 337MB
ROUTINE ======================== github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run in /workspace/go-pprof-practice/animal/canidae/dog/dog.go
336MB 336MB (flat, cum) 99.70% of Total
. . 38: log.Println(d.Name(), "pee")
. . 39:}
. . 40:
. . 41:func (d *Dog) Run() {
. . 42: log.Println(d.Name(), "run")
336MB 336MB 43: _ = make([]byte, 16*constant.Mi)
. . 44:}
. . 45:
. . 46:func (d *Dog) Howl() {
. . 47: log.Println(d.Name(), "howl")
. . 48:}
可以看到Dog.Run创建了16MB的字节数组没有使用, 因此每次gc就会被清理掉
后续排查的原理都类似, 略去命令输出
协程泄露
go tool pprof http://localhost:6060/debug/pprof/goroutine
排查到函数会创建空协程
func (w *Wolf) Drink() {
log.Println(w.Name(), "drink")
for i := 0; i < 10; i++ {
go func() { time.Sleep(30 * time.Second) }()
}
}
锁争用
go tool pprof http://localhost:6060/debug/pprof/mutex
func (w *Wolf) Howl() {
log.Println(w.Name(), "howl")
m := &sync.Mutex{}
m.Lock()
go func() {
time.Sleep(time.Second)
m.Unlock()
}()
m.Lock()
}
协程在Sleep时持有了锁
阻塞操作
go tool pprof http://localhost:6060/debug/pprof/block
func (c *Cat) Pee() {
log.Println(c.Name(), "pee")
<-time.After(time.Second)
}
channel 读取数据时发生了阻塞
pprof 同样支持http形式展现, 可以有火焰图.
pprof 原理
- 采样 如通过定时发送 SIGPROF 信号, 记录堆栈
- hook 堆分配头加入prof信息, 创建go routine时, 自动跟踪记录信息等.
引用链接
wolfogre/go-pprof-practice: go pprof practice. (github.com) golang pprof 实战 | Wolfogre's Blog
