0%

Golang性能分析工具pprof使用总结

pprof是Golang自带的一款开箱即用的性能监控和分析工具, 使用非常简单方便。

1. pprof使用

pprof使用主要有两种方式,一种是在项目中导入runtime/pprof,另一种是导入net/http/pprof, 两者的差异如下:

  • runtime/pprof: runtime/pprof提供各种相对底层的API用于生成采样数据,可以调用runtime.StartCPUProfile或者runtime.StopCPUProfile等API来生成和写入采样文件,灵活性高。
  • net/http/pprof: 通过http服务获取Profile采样文件,简单易用,适用于对应用程序的整体监控。net/http/pprof中只是使用runtime/pprof包来进行封装了一下,并在http端口上暴露出来, 如果你的程序中原本就会启动http服务,用net/http/pprof会非常方便,基本不需要主动在程序中调用代码采集和输出性能分析结果。

使用示例如下:

  • runtime/pprof
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
package main

import (
"fmt"
"os"
"runtime/pprof"
"time"
)

func main() {
// 创建分析文件
file, err := os.Create("./cpu.prof")
if err != nil {
fmt.Printf("创建采集文件失败, err:%v\n", err)
return
}

// 进行cpu数据的获取
pprof.StartCPUProfile(file)
defer pprof.StopCPUProfile()

time.Sleep(10 * time.Second)
}

之后通过命令行分析cpu.prof文件进行性能分析,由于该方式使用不多,这里不进行深度总结,感兴趣可以查阅相关文章,这次我们重点力总结http形式采集数据。

  • net/http/pprof

http形式使用十分简单,importnet/http/pprof即可,会自动调用package里面的init方法,进行初始化,如下:

1
2
3
4
5
import _ "net/http/pprof"

go func() {
http.ListenAndServe("localhost:8080", nil)
}()

之后就可以通过 http://localhost:8080/debug/pprof/[类型] 获取对应的采样数据。支持的”[类型]”有:

类型 描述
allocs 存分配情况的采样信息
blocks 阻塞操作情况的采样信息
cmdline 显示程序启动命令参数及其参数
goroutine 显示当前所有协程的堆栈信息
heap 上的内存分配情况的采样信息
mutex 竞争情况的采样信息
profile cpu占用情况的采样信息,点击会下载文件
threadcreate 系统线程创建情况的采样信息
trace 程序运行跟踪信息

pprof

重点我们关注以下几种类型:

  • profile: 获取程序当前CPU占用情况;
  • goroutine: 获取程序当前所有goroutine的堆栈信息;
  • heap: 包含每个goroutine分配大小,分配堆栈等。每分配runtime.MemProfileRate(默认为512K)个字节进行一次数据采样;
  • threadcreate: 获取导致创建OS线程的goroutine堆栈;
  • block: 获取导致阻塞的goroutine堆栈(如channel, mutex等),使用前需要先调用runtime.SetBlockProfileRate;
  • mutex: 获取导致 mutex 争用的goroutine堆栈,使用前需要先调用runtime.SetMutexProfileFraction;

2. 分析实践

2.1 CPU使用分析

通过以下命令分析CPU使用情况。

1
go tool pprof http://localhost:8080/debug/pprof/profile  

等待30秒后,执行top命令可以看到如下结果:

pprof

先简单了解一下结果中flat,sum,cum的含义:

类型 描述 举例
flat 该函数占用CPU的耗时 selectnbrecv占用CPU的耗时是12.29s
flat% 该函数占用CPU的耗时的百分比 selectnbrecv耗时:12.29s,cpu总耗时:29.14,12.29/29.14=42.18
sum% top命令中排在它上面的函数以及本函数flat%之和 chanrecv:42.18%+30.47% = 72.65%
cum 当前函数加上该函数调用之前的累计CPU耗时 chanrecv:8.88+0.54=9.42
cum% 当前函数加上该函数调用之前的累计CPU耗时的百分比 9.42/29.14=32.33%

通过以上结果,我们可以看到占用CPU比较高的方法,接下来可以通过list WirteString(list+方法名)查看占用CPU最高的方法代码明细:

pprof

通过代码明细我们可以看到,字符串拼接占用的CPU资源最多,可以针对这行代码进行优化。

2.2 内存使用分析

内存使用分析我们可以直接在网页上点击heap标签进行查看,如下:

pprof

pprof

直接在网页上查看并不是特别便利,一般情况下我们采用go tool pprof命令下载Profile采样文件进行可视化分析, 可采用如下命令:

1
go tool pprof --http=:1234 go tool pprof http://localhost:8080/debug/pprof/heap

以上命令会打开一个网页,页面效果如下:

pprof

左上的下拉条可以选择不同的可视化方式查看不同的数据:

pprof

选项卡SAMPLEspace相关是展示内存大小,单位是Byte;而objects相关展示的对象,单位是个,是有差异的。例如inuse_space展示的是现在正在使用的内存,被分配但是还没有被释放,alloc_space展示的是程序启动到现在的分配内存,包括那些已经被释放的内存,我们一般用这个来定位代码中创建临时变量的大户;

通过VIEW选项卡,我们可以切换不同的视图形式来查看分析结果。

pprof

Top

pprof

源码形式

pprof

火焰图形式

pprof

2.3 协程分析

协程分析我们可以直接在网页上点击goroutine标签进行查看, 也可以采用go tool pprof命令下载采样文件进行可视化分析。

goroutine分析页面我们可以看到协程数量和每个方法产生的协程数量。

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
41
42
goroutine profile: total 108
83 @ 0x438196 0x40666c 0x406098 0xc10cbd 0x4687c1
# 0xc10cbc jzserver/core/os/gtimer.(*Timer).loop.func1+0x7c /Documents/gotest/core/os/gtimer/gtimer_timer_loop.go:15

11 @ 0x438196 0x447f32 0x91ac0c 0x4687c1
# 0x91ac0b jzserver/core/net/gnet.(*MsgHandler).startOneWorker+0xab /Documents/gotest/core/net/gnet/gnet_msg_handler.go:76

1 @ 0x40bb54 0x464f18 0xc13279 0x4687c1
# 0x464f17 os/signal.signal_recv+0x97 /go/go1.17.6/src/runtime/sigqueue.go:169
# 0xc13278 os/signal.loop+0x18 /go/go1.17.6/src/os/signal/signal_unix.go:24

1 @ 0x438196 0x40666c 0x406098 0xc1509c 0xd8a1a5 0x437dc7 0x4687c1
# 0xc1509b jzserver/main/internal.WaitStopSignal+0xbb /Documents/gotest/main/internal/signal.go:15
# 0xd8a1a4 main.main+0x144 /Documents/gotest/main/game_server.go:75
# 0x437dc6 runtime.main+0x226 /go/go1.17.6/src/runtime/proc.go:255

1 @ 0x438196 0x40666c 0x406098 0xc1536c 0x4687c1
# 0xc1536b jzserver/main/internal.WaitReloadConfigSignal.func1+0x2b /Documents/gotest/main/internal/signal.go:47

1 @ 0x438196 0x40666c 0x4060d8 0xc45431 0x4687c1
# 0xc45430 jzserver/core/net/gwebsocket.(*Server).Run+0x30 /Documents/gotest/core/net/gwebsocket/gwebsocket_server.go:152

1 @ 0x438196 0x430813 0x463069 0x4cecf2 0x4d005a 0x4d0048 0x5f5829 0x602685 0x4abb3a 0xc0c1d3 0xc0c1ae 0x4687c1
# 0x463068 internal/poll.runtime_pollWait+0x88 /go/go1.17.6/src/runtime/netpoll.go:234
# 0x4cecf1 internal/poll.(*pollDesc).wait+0x31 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:84
# 0x4d0059 internal/poll.(*pollDesc).waitRead+0x259 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:89
# 0x4d0047 internal/poll.(*FD).Read+0x247 /go/go1.17.6/src/internal/poll/fd_unix.go:167
# 0x5f5828 net.(*netFD).Read+0x28 /go/go1.17.6/src/net/fd_posix.go:56
# 0x602684 net.(*conn).Read+0x44 /go/go1.17.6/src/net/net.go:183
# 0x4abb39 io.ReadAtLeast+0x99 /go/go1.17.6/src/io/io.go:328
# 0xc0c1d2 io.ReadFull+0x132 /go/go1.17.6/src/io/io.go:347
# 0xc0c1ad jzserver/core/net/gtcp.(*Connection).StartReader+0x10d /Documents/gotest/core/net/gtcp/gtcp_connection.go:100

1 @ 0x438196 0x430813 0x463069 0x4cecf2 0x4d005a 0x4d0048 0x5f5829 0x602685 0x6c57df 0x4687c1
# 0x463068 internal/poll.runtime_pollWait+0x88 /go/go1.17.6/src/runtime/netpoll.go:234
# 0x4cecf1 internal/poll.(*pollDesc).wait+0x31 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:84
# 0x4d0059 internal/poll.(*pollDesc).waitRead+0x259 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:89
# 0x4d0047 internal/poll.(*FD).Read+0x247 /go/go1.17.6/src/internal/poll/fd_unix.go:167
# 0x5f5828 net.(*netFD).Read+0x28 /go/go1.17.6/src/net/fd_posix.go:56
# 0x602684 net.(*conn).Read+0x44 /go/go1.17.6/src/net/net.go:183
# 0x6c57de net/http.(*connReader).backgroundRead+0x3e /go/go1.17.6/src/net/http/server.go:672

我们将链接后面的debug=1改为debug=2(以unrecovered panic的格式打印堆栈,可读性更高),可以见到各协程等待时长,可用于分析goroutine泄漏

pprof

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
41
42
43
44
45
goroutine 57914819 [running]:
runtime/pprof.writeGoroutineStacks({0x10a4760, 0xc000990fc0})
/gotest/go1.17.6/src/runtime/pprof/pprof.go:693 +0x70
runtime/pprof.writeGoroutine({0x10a4760, 0xc000990fc0}, 0x0)
/gotest/go1.17.6/src/runtime/pprof/pprof.go:682 +0x2b
runtime/pprof.(*Profile).WriteTo(0xeadca0, {0x10a4760, 0xc000990fc0}, 0xc)
/gotest/go1.17.6/src/runtime/pprof/pprof.go:331 +0x14b
net/http/pprof.handler.ServeHTTP({0xc000952191, 0x1822580}, {0x10bd528, 0xc000990fc0}, 0xc000952184)
/gotest/go1.17.6/src/net/http/pprof/pprof.go:253 +0x49a
net/http/pprof.Index({0x10bd528, 0xc000990fc0}, 0xc000ca8300)
/gotest/go1.17.6/src/net/http/pprof/pprof.go:371 +0x12e
net/http.HandlerFunc.ServeHTTP(0x0, {0x10bd528, 0xc000990fc0}, 0x0)
/gotest/go1.17.6/src/net/http/server.go:2047 +0x2f
net/http.(*ServeMux).ServeHTTP(0xc00095219b, {0x10bd528, 0xc000990fc0}, 0xc000ca8300)
/gotest/go1.17.6/src/net/http/server.go:2425 +0x149
net/http.serverHandler.ServeHTTP({0xc00168d800}, {0x10bd528, 0xc000990fc0}, 0xc000ca8300)
/gotest/go1.17.6/src/net/http/server.go:2879 +0x43b
net/http.(*conn).serve(0xc0015f5220, {0x10c06c0, 0xc000472210})
/gotest/go1.17.6/src/net/http/server.go:1930 +0xb08
created by net/http.(*Server).Serve
/gotest/go1.17.6/src/net/http/server.go:3034 +0x4e8

goroutine 1 [chan receive, 7547 minutes]:
jzserver/main/internal.WaitStopSignal()
/gotest/main/internal/signal.go:15 +0xbc
main.main()
/gotest/main/game_server.go:75 +0x145

goroutine 50 [select, 48 minutes]:
database/sql.(*DB).connectionCleaner(0xc0000a24e0, 0xc0001ca8d0)
/gotest/go1.17.6/src/database/sql/sql.go:1068 +0xbd
created by database/sql.(*DB).startCleanerLocked
/gotest/go1.17.6/src/database/sql/sql.go:1055 +0x105

goroutine 49 [chan receive]:
jzserver/core/os/gtimer.(*Timer).loop.func1()
/gotest/core/os/gtimer/gtimer_timer_loop.go:15 +0x7d
created by jzserver/core/os/gtimer.(*Timer).loop
/gotest/core/os/gtimer/gtimer_timer_loop.go:7 +0x5b

goroutine 6 [select, 7547 minutes]:
database/sql.(*DB).connectionOpener(0xc0000a24e0, {0x10c0618, 0xc00021c440})
/gotest/go1.17.6/src/database/sql/sql.go:1196 +0x93
created by database/sql.OpenDB
/gotest/go1.17.6/src/database/sql/sql.go:794 +0x188

3. 其他总结

  • heap不能直接用于分析内存泄漏情况,但可以用分析内存使用情况。内存泄漏分析相关文章可见: 实战Go内存泄露
  • 我们在http形式获取的采样数据中,可以看到heap一直在增长,是因为heap是自程序启动开始运行,每分配runtime.MemProfileRate(默认为512K)个字节进行一次数据采样,便于分析自程序启动以来alloc_objects,alloc_space 和当前使用使用的inuse_objects,inuse_space;
  • pprof生成的prof文件时二进制的,我们通过web形式查看的话,需要把这个二进制的文件转换为可读的,graphviz可以帮助我们把二进制的prof文件转换为图像。Mac安装:
1
brew install graphviz

其他系统安装参考这里Graphviz Download。

4. 参考文章