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

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方法，进行初始化，如下：

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	程序运行跟踪信息

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

• 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使用情况。

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

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

先简单了解一下结果中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最高的方法代码明细:

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

2.2 内存使用分析

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

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

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

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

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

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

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

Top

源码形式

火焰图形式

2.3 协程分析

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

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

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泄漏

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安装:

brew install graphviz

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

4. 参考文章

• go pprof 性能分析
• 实战Go内存泄露