准备工作
1、安装graphviz
Go语言的内置工具可以借助graphviz软件将性能分析结果图形化。
OS X和Ubuntu可以直接使用brew和apt-get install graphviz
Windows用户可以下载zip包，然后将解压后的目录添加到Path环境变量中。
下载地址：http://www.graphviz.org/download/
2、将$GOPATH/bin目录添加到Path环境变量中
在代码中嵌入性能分析代码
这种方式可以很灵活的对任何代码片段进行性能分析。
示例代码（prof.go）：
package main
import (
"log"
"math/rand"
"os"
"runtime"
"runtime/pprof"
"time"
)
const (
col = 10000
row = 10000
)
func fillMatrix(m *[row][col]int) {
s := rand.New(rand.NewSource(time.Now().UnixNano()))
for i := 0; i < row; i++ {
for j := 0; j < col; j++ {
m[i][j] = s.Intn(100000)
}
}
}
func calculate(m *[row][col]int) {
for i := 0; i < row; i++ {
tmp := 0
for j := 0; j < col; j++ {
tmp += m[i][j]
}
}
}
func main() {
//创建输出文件
f, err := os.Create("cpu.prof")
if err != nil {
log.Fatal("could not create CPU profile: ", err)
}
// 获取系统信息
if err := pprof.StartCPUProfile(f); err != nil { //监控cpu
log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()
// 主逻辑区，进行一些简单的代码运算
x := [row][col]int{}
fillMatrix(&x)
calculate(&x)
f1, err := os.Create("mem.prof")
if err != nil {
log.Fatal("could not create memory profile: ", err)
}
//runtime.GC() // GC，获取最新的数据信息
if err := pprof.WriteHeapProfile(f1); err != nil { // 写入内存信息
log.Fatal("could not write memory profile: ", err)
}
f1.Close()
f2, err := os.Create("goroutine.prof")
if err != nil {
log.Fatal("could not create groutine profile: ", err)
}
if gProf := pprof.Lookup("goroutine"); gProf == nil {
log.Fatal("could not write groutine profile: ")
} else {
gProf.WriteTo(f2, 0)
}
f2.Close()
}
示例代码中只写了两个功能函数，分别是fillMatrix、calculate。
fillMatrix会使用随机数初始化传入的二维数组，calculate会计算二维数组每行元素的累加和。
在main函数中，通过StartCPUProfile和StopCPUProfile函数来生成程序运行时的CPU占用情况。可以通过控制两个函数的调用位置来生成特定代码片段的运行时CPU占用情况。
后面又调用了WriteHeapProfile函数来生成程序运行时的内存占用情况。
在程序末尾，通过Lookup和WriteTo函数生成了当前所在协程的profile文件。
编译并运行这段代码，会生成三个profile文件：
$ go build prof.go
$ ./prof.exe
$ ls
cpu.prof goroutine.prof mem.prof prof.exe* prof.go
使用go tool pprof分析cpu性能
$ go tool pprof cpu.prof
Type: cpu
Time: Feb 25, 2020 at 3:36pm (CST)
Duration: 2.12s, Total samples = 2s (94.37%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.98s, 99.00% of 2s total
Showing top 10 nodes out of 28
flat flat% sum% cum cum%
0.77s 38.50% 38.50% 1.09s 54.50% math/rand.(*Rand).Int31n
0.59s 29.50% 68.00% 1.93s 96.50% main.fillMatrix
0.25s 12.50% 80.50% 1.34s 67.00% math/rand.(*Rand).Intn
0.14s 7.00% 87.50% 0.14s 7.00% math/rand.(*rngSource).Uint64
0.08s 4.00% 91.50% 0.32s 16.00% math/rand.(*Rand).Int31
0.07s 3.50% 95.00% 0.21s 10.50% math/rand.(*rngSource).Int63
0.03s 1.50% 96.50% 0.03s 1.50% main.calculate
0.03s 1.50% 98.00% 0.24s 12.00% math/rand.(*Rand).Int63
0.01s 0.5% 98.50% 0.01s 0.5% runtime.cgocall
0.01s 0.5% 99.00% 0.01s 0.5% runtime.globrunqget
(pprof) list main.fillMatrix
Total: 2s
ROUTINE ======================== main.fillMatrix in D:\project_root\gogogo\hello_test\src\pprof\prof.go
590ms 1.93s (flat, cum) 96.50% of Total
. . 15:)
. . 16:
. . 17:func fillMatrix(m *[row][col]int) {
. . 18: s := rand.New(rand.NewSource(time.Now().UnixNano()))
. . 19:
10ms 10ms 20: for i:=0; i<row; i++ {
90ms 90ms 21: for j:=0; j<col; j++ {
490ms 1.83s 22: m[i][j] = s.Intn(100000)
. . 23: }
. . 24: }
. . 25:}
. . 26:
. . 27:func calculate(m *[row][col] int) {
(pprof) svg
Generating report in profile001.svg
(pprof) exit
$ ls
cpu.prof goroutine.prof mem.prof prof.exe* prof.go profile001.svg
上面的命令中，首先使用go tool pprof cpu.prof命令打开一个分析cpu.prof文件的交互式命令行，在交互命令行中使用top命令可以查看各个函数的cpu运行时间占比数据。
cum cum%代表函数以及函数调用其他函数的整体cpu运行时间和总体占比。
flat flat% 两列代表函数本身（不包含调用其他函数的耗时）运行的cpu运行时间和总体占比。
在命令输出中，我们可以看到：
0.59s 29.50% 68.00% 1.93s 96.50% main.fillMatrix
main.fillMatrix函数调用耗时较长，因为我们使用list main.fillMatrix命令来详细查看这个函数每一条语句的cpu耗时情况：
(pprof) list main.fillMatrix
Total: 2s
ROUTINE ======================== main.fillMatrix in D:\project_root\gogogo\hello_test\src\pprof\prof.go
590ms 1.93s (flat, cum) 96.50% of Total
. . 15:)
. . 16:
. . 17:func fillMatrix(m *[row][col]int) {
. . 18: s := rand.New(rand.NewSource(time.Now().UnixNano()))
. . 19:
10ms 10ms 20: for i:=0; i<row; i++ {
90ms 90ms 21: for j:=0; j<col; j++ {
490ms 1.83s 22: m[i][j] = s.Intn(100000)
. . 23: }
. . 24: }
. . 25:}
. . 26:
. . 27:func calculate(m *[row][col] int) {
通过命令行输出，很容易发现main.fillMatrix函数调用耗费的大部分时间都花在了s.Intn(100000)语句上（随机数生成）。
交互式命令的最后，使用了svg命令，借助博客最前面安装的graphviz软件生成可视化的cpu耗时分析图，使用浏览器打开生成的svg文件，可以很直观的看到函数调用过程中的cpu耗时情况：
基本上，显示的方块越大，就代表cpu耗时越长。
也有人习惯使用go-torch工具通过火炬图的方式进行分析，只是展示方式有所不通，这里不做介绍。
使用go tool pprof分析mem性能
分析内存性能的pprof命令用法与分析cpu性能用法基本一致：
$ go tool pprof mem.prof
Type: inuse_space
Time: Feb 25, 2020 at 3:36pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 762.95MB, 99.85% of 764.10MB total
Dropped 1 node (cum <= 3.82MB)
flat flat% sum% cum cum%
762.95MB 99.85% 99.85% 764.10MB 100% main.main
0 0% 99.85% 764.10MB 100% runtime.main
(pprof) list main.main
Total: 764.10MB
ROUTINE ======================== main.main in D:\project_root\gogogo\hello_test\src\pprof\prof.go
762.95MB 764.10MB (flat, cum) 100% of Total
. . 37: f, err := os.Create("cpu.prof")
. . 38: if err != nil {
. . 39: log.Fatal("could not create cpu profile: ", err)
. . 40: }
. . 41:
. 1.16MB 42: if err := pprof.StartCPUProfile(f); err != nil {
. . 43: log.Fatal("could not start cpu profile: ", err)
. . 44: }
. . 45:
. . 46: defer pprof.StopCPUProfile()
. . 47:
762.95MB 762.95MB 48: x := [row][col]int {}
. . 49: fillMatrix(&x)
. . 50: calculate(&x)
. . 51:
. . 52: f1, err := os.Create("mem.prof")
. . 53: if err != nil {
(pprof)
这里分析的是mem.prof文件，使用的命令同样是top和list。
通过top和list命令的执行结果，不难发现，程序内存分配大部分都集中在在48行的二维数组的初始化位置（x := [row][col]int {}）。
在最前面的代码里有一条被注释掉了的runtime.GC() 调用，你可以尝试去除注释，然后重新生成mem.prof文件，再使用go tool pprof mem.prof命令进行分析，看看Go语言的GC有没有起作用。
使用go tool pprof分析goroutine（协程）性能
用法与前面分析cpu和mem用法一致。
通过http方式输出profile文件及性能分析
在Web应用场景中，程序大多通过http方式对外提供服务，Go语言中也提供了以http服务的方式输出profile的方法，获取到profile后，就可以通过pprof命令来进行分析。
需要在代码中添加的内容：
- 在代码中import _ “net/http/pprof”;
- 启动http server；
- 使用go tool pprof http:debuf/profile/profile?seconds=10（默认值30秒）打开交互命令行进行分析。
如果程序本身有http server，则第2步可以省略。
示例http server代码：
package main
import (
"fmt"
"log"
"net/http"
_ "net/http/pprof"
)
func GetFibonacciSerie(n int) []int {
ret := make([]int, 2, n)
ret[0] = 1
ret[1] = 1
for i := 2; i < n; i++ {
ret = append(ret, ret[i-2]+ret[i-1])
}
return ret
}
func index(w http.ResponseWriter, r *http.Request) {
w.Write([]byte("Welcome!"))
}
func createFBS(w http.ResponseWriter, r *http.Request) {
var fbs []int
for i := 0; i < 1000000; i++ {
fbs = GetFibonacciSerie(50)
}
w.Write([]byte(fmt.Sprintf("%v", fbs)))
}
func main() {
http.HandleFunc("/", index)
http.HandleFunc("/fb", createFBS)
log.Fatal(http.ListenAndServe(":8081", nil))
}
代码中通过net/http对外暴露了两个http接口，分别是index和createFBS，createFBS通过http形式对外开放斐波那契数列的生成服务。
运行这个http server代码：
$ go run http.go
在浏览器中测试http server：
运行go tool pprof命令分析性能：
$ go tool pprof http://127.0.0.1:8081/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://127.0.0.1:8081/debug/pprof/profile?seconds=10
在没有捕获到要分析的请求数据前，不会得到交互式命令行。
因此我们首先要在浏览器中调用待测试的服务接口：
可以多调用几次。。。
此时我们就可以获取到交互式命令行了：
$ go tool pprof http://127.0.0.1:8081/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://127.0.0.1:8081/debug/pprof/profile?seconds=10
Saved profile in C:\Users\wanhex\pprof\pprof.samples.cpu.004.pb.gz
Type: cpu
Time: Feb 25, 2020 at 4:52pm (CST)
Duration: 10.10s, Total samples = 430ms ( 4.26%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) (pprof)
(pprof) top -cum
Showing nodes accounting for 130ms, 30.23% of 430ms total
Showing top 10 nodes out of 78
flat flat% sum% cum cum%
100ms 23.26% 23.26% 220ms 51.16% main.GetFibonacciSerie
0 0% 23.26% 220ms 51.16% main.createFBS
0 0% 23.26% 220ms 51.16% net/http.(*ServeMux).ServeHTTP
0 0% 23.26% 220ms 51.16% net/http.(*conn).serve
0 0% 23.26% 220ms 51.16% net/http.HandlerFunc.ServeHTTP
0 0% 23.26% 220ms 51.16% net/http.serverHandler.ServeHTTP
0 0% 23.26% 190ms 44.19% runtime.systemstack
10ms 2.33% 25.58% 120ms 27.91% runtime.makeslice
10ms 2.33% 27.91% 110ms 25.58% runtime.mallocgc
10ms 2.33% 30.23% 80ms 18.60% runtime.(*mcache).nextFree
(pprof) list main.createFBS
Total: 430ms
ROUTINE ======================== main.createFBS in D:\project_root\gogogo\hello_test\src\pprof\http.go
0 220ms (flat, cum) 51.16% of Total
. . 22:}
. . 23:
. . 24:func createFBS(w http.ResponseWriter, r *http.Request) {
. . 25: var fbs []int
. . 26: for i := 0; i < 1000000; i++ {
. 220ms 27: fbs = GetFibonacciSerie(50)
. . 28: }
. . 29: w.Write([]byte(fmt.Sprintf("%v", fbs)))
. . 30:
. . 31:}
. . 32:
(pprof) list main.GetFibonacciSerie
Total: 430ms
ROUTINE ======================== main.GetFibonacciSerie in D:\project_root\gogogo\hello_test\src\pprof\http.go
100ms 220ms (flat, cum) 51.16% of Total
. . 6: "net/http"
. . 7: _ "net/http/pprof"
. . 8:)
. . 9:
. . 10:func GetFibonacciSerie(n int) []int {
. 120ms 11: ret := make([]int, 2, n)
. . 12: ret[0] = 1
10ms 10ms 13: ret[1] = 1
20ms 20ms 14: for i := 2; i < n; i++ {
60ms 60ms 15: ret = append(ret, ret[i-2]+ret[i-1])
. . 16: }
10ms 10ms 17: return ret
. . 18:}
. . 19:
. . 20:func index(w http.ResponseWriter, r *http.Request) {
. . 21: w.Write([]byte("Welcome!"))
. . 22:}
(pprof)
这里我们同样使用top和list命令来分析cpu性能。
此处的top命令使用-cum参数来对函数调用时累计cpu耗时进行排序后再输出。
测试用例代码中生成profile及性能分析
如果调用功能函数的代码是测试用例代码，则可以以非侵入的方式获取到profile文件。
具体获取profile文件及性能分析方法，可参见博客《二、Golang性能调优示例》
注：
博客内容为极客时间视频课《Go语言从入门到实战》学习笔记。
参考课程链接：
https://time.geekbang.org/course/intro/160?code=NHxez89MnqwIfa%2FvqTiTIaYof1kxYhaEs6o2kf3ZxhU%3D&utm_term=SPoster
博客参考代码：
https://github.com/geektime-geekbang/go_learning/tree/master/code/ch46
若访问github较慢，可使用加速器：
http://91tianlu.date/aff.php?aff=3468
扫一扫
1977
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
