Gitlib
Ravior
2021-07-10
目录

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)
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

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

  • net/http/pprof

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

import _ "net/http/pprof"

go func() {
   http.ListenAndServe("localhost:8080", nil)
}()
1
2
3
4
5

之后就可以通过 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使用情况。

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

等待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采样文件进行可视化分析, 可采用如下命令:

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

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

pprof

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

pprof

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

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

pprof

Top

pprof

源码形式

pprof

火焰图形式

pprof

# 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
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

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

pprof

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

# 3. 其他总结

  • heap不能直接用于分析内存泄漏情况，但可以用分析内存使用情况。内存泄漏分析相关文章可见: 实战Go内存泄露 (opens new window)

  • 我们在http形式获取的采样数据中，可以看到heap一直在增长，是因为heap是自程序启动开始运行，每分配runtime.MemProfileRate(默认为512K)个字节进行一次数据采样，便于分析自程序启动以来alloc_objects,alloc_space 和当前使用使用的inuse_objects,inuse_space;

  • pprof生成的prof文件时二进制的，我们通过web形式查看的话，需要把这个二进制的文件转换为可读的，graphviz可以帮助我们把二进制的prof文件转换为图像。Mac安装:

brew install graphviz
1

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

# 4. 参考文章

#Golang
上次更新: 2022/12/01, 11:09:34
Golang日常开发总结
Golang源码系列-Slice

← Golang源码系列-Slice→

最近更新
01
常用游戏反外挂技术总结
11-27
02
Golang开发实践万字总结
11-11
03
Redis万字总结
10-30
更多文章>
Theme by Vdoing | Copyright © 2011-2022 Ravior | 粤ICP备17060229号-3 | MIT License