> For the complete documentation index, see [llms.txt](https://www.1024cx.top/llms.txt). Markdown versions of documentation pages are available by appending `.md` to page URLs; this page is available as [Markdown](https://www.1024cx.top/golang/optimization/pprof.md). # pprof pprof是性能分析的工具。 ## pprof可以用来做什么？ * CPU Profiling：CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置。 * Memory Profiling：内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏。 * Block Profiling：阻塞分析，记录 Goroutine 阻塞等待同步（包括定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置。 * Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置。 * Goroutine Profiling： Goroutine 分析，可以对当前应用程序正在运行的 Goroutine 进行堆栈跟踪和分析。这项功能在实际排查中会经常用到，因为很多问题出现时的表象就是 Goroutine 暴增，而这时候要做的事情之一就是查看应用程序中的 Goroutine 正在做什么事情，因为什么阻塞了，然后再进行下一步。 ## 信息采集得到的概要文件(Profile) 用于分析程序性能的概要文件有三种，分别是：CPU 概要文件（CPU Profile）、内存概要文件（Mem Profile）和阻塞概要文件（Block Profile）。 这些概要文件中包含的都是：在某一段时间内，对 Go 程序的相关指标进行多次采样后得到的概要信息。 对于 CPU 概要文件来说，其中的每一段独立的概要信息都记录着，在进行某一次采样的那个时刻，CPU 上正在执行的 Go 代码。 而对于内存概要文件，其中的每一段概要信息都记载着，在某个采样时刻，正在执行的 Go 代码以及堆内存的使用情况，这里包含已分配和已释放的字节数量和对象数量。 至于阻塞概要文件，其中的每一段概要信息，都代表着 Go 程序中的一个 goroutine 阻塞事件。 ## 信息采集之工具型应用 ```go import "runtime/pprof" // 工具型应用用这个包 ``` ### CPU执行信息采集 开启CPU信息采集： ```go pprof.StartCPUProfile(w io.Writer) ``` 停止CPU信息采集： ```go pprof.StopCPUProfile() ``` 应用执行结束后，就会生成一个文件，保存了 CPU profiling 数据。得到采样数据之后，使用`go tool pprof`工具进行程序的CPU性能问题检查。 ### 内存信息采集 记录程序的堆栈信息 ```go pprof.WriteHeapProfile(w io.Writer) ``` 应用执行结束后，就会生成另一个文件，下一步使用`go tool pprof`工具进行程序的内存问题排查。 `go tool pprof`默认是使用`-inuse_space`进行统计，还可以使用`-inuse-objects`查看分配对象的数量。 ### 使用示例 ```go package main import ( "flag" "fmt" "os" "runtime/pprof" "time" ) // 一段有问题的代码 func logicCode() { var c chan int for { select { case v := <-c: fmt.Printf("recv from chan, value:%v\n", v) default: } } } func main() { var isCPUPprof bool var isMemPprof bool flag.BoolVar(&isCPUPprof, "cpu", false, "turn cpu pprof on") flag.BoolVar(&isMemPprof, "mem", false, "turn mem pprof on") flag.Parse() if isCPUPprof { file, err := os.Create("./cpu.pprof") if err != nil { fmt.Printf("create cpu pprof failed, err:%v\n", err) return } pprof.StartCPUProfile(file) defer pprof.StopCPUProfile() } for i := 0; i < 8; i++ { go logicCode() } time.Sleep(30 * time.Second) if isMemPprof { file, err := os.Create("./mem.pprof") if err != nil { fmt.Printf("create mem pprof failed, err:%v\n", err) return } pprof.WriteHeapProfile(file) file.Close() } } ``` 通过flag可以通过命令行控制是否开启CPU和Mem的性能分析，执行时加上`-cpu`命令行参数如下： ```bash go run main.go -cpu ``` 等待30秒后会在当前目录下生成一个`cpu.pprof`文件。 ## 信息采集之服务型应用 如果应用程序是一直运行的，比如 web 应用，那么可以使用`net/http/pprof`库，它能够在提供 HTTP 服务的同时进行数据采集。 如果使用了默认的`http.DefaultServeMux`（通常是代码直接使用`http.ListenAndServe(“0.0.0.0:8000”, nil)）`，只需要在web server端代码中按如下方式导入`net/http/pprof` ```go import _ "net/http/pprof" // 服务型应用用这个包 ``` 如果使用自定义的 Mux，则需要手动注册一些路由规则： ```go r.HandleFunc("/debug/pprof/", pprof.Index) r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline) r.HandleFunc("/debug/pprof/profile", pprof.Profile) // CPU r.HandleFunc("/debug/pprof/heap", pprof.Index) // 内存 r.HandleFunc("/debug/pprof/symbol", pprof.Symbol) r.HandleFunc("/debug/pprof/trace", pprof.Trace) ``` 如果使用的是gin框架，那么推荐使用[github.com/gin-contrib/pprof](https://github.com/gin-contrib/pprof)，在代码中通过以下命令注册pprof相关路由。 ```go pprof.Register(router) ``` 不管哪种方式，都可以通过访问上述路由查看相关内容： * /debug/pprof/profile：访问这个链接会自动进行 CPU profiling，持续 30s，并生成一个文件供下载 * /debug/pprof/heap： Memory Profiling 的路径，访问这个链接会得到一个内存 Profiling 结果的文件 * /debug/pprof/block：block Profiling 的路径 * /debug/pprof/goroutines：运行的 goroutines 列表，以及调用关系 ## 对采集的数据进行分析 不管是工具型应用还是服务型应用，使用相应的pprof库获取到数据文件之后，下一步都要对这些数据进行分析检查。 ```bash go tool pprof [binary] [source] ``` 其中： * binary 是应用的二进制文件，用来解析各种符号； * source 表示 profile 数据的来源，可以是本地的文件，也可以是 http 地址。 **注意事项：** 获取的 Profiling 数据是动态的，要想获得有效的数据，请保证应用处于较大的负载（比如正在生成中运行的服务，或者通过其他工具模拟访问压力）。否则如果应用处于空闲状态，得到的结果可能没有任何意义。 ## CPU Profiling 分析使用示例 以上述代码为案例，生成了`cpu.pprof`文件，然后在命令行执行： ```bash go tool pprof cpu.pprof ``` 执行上面的代码会进入交互界面如下： ```bash runtime_pprof $ go tool pprof cpu.pprof Type: cpu Time: Jun 28, 2019 at 11:28am (CST) Duration: 20.13s, Total samples = 1.91mins (568.60%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) ``` 接下来可以在交互界面输入`top3`来查看程序中占用CPU前3位的函数： ```bash (pprof) top3 Showing nodes accounting for 100.37s, 87.68% of 114.47s total Dropped 17 nodes (cum <= 0.57s) Showing top 3 nodes out of 4 flat flat% sum% cum cum% 42.52s 37.15% 37.15% 91.73s 80.13% runtime.selectnbrecv 35.21s 30.76% 67.90% 39.49s 34.50% runtime.chanrecv 22.64s 19.78% 87.68% 114.37s 99.91% main.logicCode ``` 其中： * flat：仅当前函数的CPU耗时(不含它内部调用函数的执行时间) * flat%：当前函数CPU耗时百分比 * sum%：仅当前函数的CPU耗时累计百分比(不含它内部调用函数的执行时间) * cum：当前函数加上该函数内部调用函数的CPU总耗时 * cum%：当前函数加上该函数内部调用函数的CPU总耗时百分比 * 最后一列：函数名称 在列表中找出自己编写的函数，可以看出，`main.logicCode`对CPU的消耗过高，接下来使用`list`命令对该函数的实现代码CPU耗时进行下一步检查： ```bash (pprof) list logicCode Total: 1.82mins ROUTINE ======================== main.logicCode in /Users/zhhnzw/workspace/mygithub/chat/t.go 23.19s 1.82mins (flat, cum) 100% of Total . . 11:// 一段有问题的代码 . . 12:func logicCode() { . . 13: var c chan int . . 14: for { . . 15: select { 23.19s 1.82mins 16: case v := <-c: . . 17: fmt.Printf("recv from chan, value:%v\n", v) . . 18: default: . . 19: . . 20: } . . 21: } ``` 通过检查发现大部分CPU资源被第16行占用，`select`语句中的default没有内容会导致`select`代码块不会发生阻塞，从而`case v:=<-c:`被`for`无限制的循环执行，浪费了CPU资源。解决办法：可以在default分支里添加一行`time.Sleep(time.Second)`。 ## Goroutine、Mutex、Block 分析使用示例 ```go package main import ( "net/http" _ "net/http/pprof" "runtime" "sync" ) func init() { runtime.SetMutexProfileFraction(1) // 默认不采集互斥锁，需要手动设置 runtime.SetBlockProfileRate(1) // 默认不采集阻塞信息，需要手动设置 } func WriteMap() { var m sync.Mutex var datas = make(map[int]struct{}) for i := 0; i < 999; i++ { go func(i int) { m.Lock() defer m.Unlock() datas[i] = struct{}{} }(i) } } func main() { go func() { for { WriteMap() } }() _ = http.ListenAndServe(":6060", nil) } ``` ### Goroutine Profiling ```bash $ go tool pprof http://localhost:6060/debug/pprof/goroutine Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine Saved profile in /Users/zhhnzw/pprof/pprof.goroutine.006.pb.gz Type: goroutine Time: Apr 14, 2022 at 3:27pm (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof) ``` 使用`traces`命令，会打印出对应的所有调用栈，以及指标信息，可以查看到整个调用链路有什么，分别在哪里使用了多少个 goroutine，并且能够通过分析查看到谁才是真正的调用方： ```bash (pprof) traces Type: goroutine Time: Apr 14, 2022 at 3:27pm (CST) -----------+------------------------------------------------------- 1291 runtime.gopark runtime.goparkunlock (inline) runtime.semacquire1 sync.runtime_SemacquireMutex sync.(*Mutex).lockSlow sync.(*Mutex).Lock (inline) main.WriteMap.func1 -----------+------------------------------------------------------- 1 runtime.newobject main.WriteMap main.main.func1 -----------+------------------------------------------------------- 1 runtime.blockevent runtime.semacquire1 sync.runtime_SemacquireMutex sync.(*Mutex).lockSlow sync.(*Mutex).Lock (inline) main.WriteMap.func1 -----------+------------------------------------------------------- 1 runtime.gopark runtime.netpollblock internal/poll.runtime_pollWait internal/poll.(*pollDesc).wait internal/poll.(*pollDesc).waitRead (inline) internal/poll.(*FD).Read net.(*netFD).Read net.(*conn).Read net/http.(*connReader).backgroundRead -----------+------------------------------------------------------- 1 runtime.gopark runtime.netpollblock internal/poll.runtime_pollWait internal/poll.(*pollDesc).wait internal/poll.(*pollDesc).waitRead (inline) internal/poll.(*FD).Accept net.(*netFD).accept net.(*TCPListener).accept net.(*TCPListener).Accept net/http.(*Server).Serve net/http.(*Server).ListenAndServe net/http.ListenAndServe (inline) main.main runtime.main -----------+------------------------------------------------------- 1 runtime.goready runtime.readyWithTime runtime.semrelease1 sync.runtime_Semrelease sync.(*Mutex).unlockSlow sync.(*Mutex).Unlock main.WriteMap.func1 -----------+------------------------------------------------------- 1 runtime.goyield (inline) runtime.semrelease1 sync.runtime_Semrelease sync.(*Mutex).unlockSlow sync.(*Mutex).Unlock main.WriteMap.func1 -----------+------------------------------------------------------- 1 runtime/pprof.runtime_goroutineProfileWithLabels runtime/pprof.writeRuntimeProfile runtime/pprof.writeGoroutine runtime/pprof.(*Profile).WriteTo net/http/pprof.handler.ServeHTTP net/http/pprof.Index net/http.HandlerFunc.ServeHTTP net/http.(*ServeMux).ServeHTTP net/http.serverHandler.ServeHTTP net/http.(*conn).serve -----------+------------------------------------------------------- ``` 在调用栈上来讲，其展示顺序是自下而上的，以第5栏为例，`runtime.main`方法调用了`main.main`方法，`main.main`方法又调用了 `net/http.ListenAndServe`方法，这里对应的也就是所使用的示例代码了，结合代码来排查会非常方便，也可以用`web`指令来可视化`traces`调用链，排查起来就更加方便了，可视化见下一个小节。 `main.WriteMap.func1`对应有1291个goroutine，不断增长的goroutine数量就是协程泄露/内存泄露问题。 ### Mutex Profiling ```bash $go tool pprof http://localhost:6060/debug/pprof/mutex Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex Saved profile in /Users/zhhnzw/pprof/pprof.contentions.delay.015.pb.gz Type: delay Time: Apr 14, 2022 at 3:27pm (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top5 Showing nodes accounting for 85.65s, 100% of 85.65s total flat flat% sum% cum cum% 85.65s 100% 100% 85.65s 100% sync.(*Mutex).Unlock 0 0% 100% 85.65s 100% main.WriteMap.func1 (pprof) list main.WriteMap.func1 Total: 85.65s ROUTINE ======================== main.WriteMap.func1 in /Users/zhhnzw/workspace/mygithub/go_demos/main.go 0 85.65s (flat, cum) 100% of Total . . 18: for i := 0; i < 999; i++ { . . 19: go func(i int) { . . 20: m.Lock() . . 21: defer m.Unlock() . . 22: datas[i] = struct{}{} . 85.65s 23: }(i) . . 24: } . . 25:} . . 26: . . 27:func main() { . . 28: go func() { ``` 先用`top`命令，查看互斥量的排名，然后执行`list+函数名`命令可以查看该函数具体是哪一行代码导致了锁开销，如上是23行。 ### Block Profiling ```bash $go tool pprof http://localhost:6060/debug/pprof/block Fetching profile over HTTP from http://localhost:6060/debug/pprof/block Saved profile in /Users/zhhnzw/pprof/pprof.contentions.delay.016.pb.gz Type: delay Time: Apr 14, 2022 at 3:27pm (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top5 Showing nodes accounting for 5.20hrs, 100% of 5.20hrs total Dropped 4 nodes (cum <= 0.03hrs) flat flat% sum% cum cum% 5.20hrs 100% 100% 5.20hrs 100% sync.(*Mutex).Lock (inline) 0 0% 100% 5.20hrs 100% main.WriteMap.func1 ``` 如上可知，是`main.WriteMap.func1`内部的`sync.(*Mutex).Lock`产生的阻塞。 ## 用可视化工具分析 Mac下安装： ```bash brew install graphviz ``` ### web指令 在`pprof`命令行： ```bash (pprof) web ``` ![pprof 可视化 web](/files/-M_a6laEAFQ9ep07ocxT) 关于图形的说明： 每个框代表一个函数，理论上框越大表示占用的CPU资源越多。 方框之间的线条代表函数之间的调用关系。 线条上的数字表示函数调用耗费的时间。 方框中的第一行数字表示仅当前函数消耗的CPU耗时(sum，不是sum%)，第二行数字表示当前函数加上该函数调用函数的占用CPU总耗时cum。 除了分析CPU性能数据，pprof也支持分析内存性能数据。比如，使用下面的命令分析http服务的heap性能数据，查看当前程序的内存占用以及热点内存对象使用的情况。 ```bash # 查看内存占用数据 go tool pprof -inuse_space http://127.0.0.1:8080/debug/pprof/heap go tool pprof -inuse_objects http://127.0.0.1:8080/debug/pprof/heap # 查看临时内存分配数据 go tool pprof -alloc_space http://127.0.0.1:8080/debug/pprof/heap go tool pprof -alloc_objects http://127.0.0.1:8080/debug/pprof/heap ``` ### 单独的站点 ```bash # 这条命令会先获取 CPU Profiling 采集文件，然后运行一个 pprof 分析用的web站点 $ go tool pprof -http=:6001 http://localhost:6060/debug/pprof/profile ``` #### Graph `VIEW`默认展示的是`Graph`分析界面： ![](/files/u0QYdxrqDh3PKRjOxjeB) #### Flame Graph(火焰图) ![](/files/mVfhYxrn5RUWUS2uibIl) 火焰图的调用顺序从上到下，每个方块代表一个函数，它下面一层表示这个函数会调用哪些函数，方块的大小代表了占用 CPU 使用的长短。火焰图的配色并没有特殊的意义，默认的红、黄配色是为了更像火焰而已。可以通过点击方块来 zoom in 检查它内部的内容深入分析，以下点击了`WriteMap.func1`区块，进入到了下一层级： ![](/files/Fa3uewmsHCpCs3ICeY6t) #### Top 跟交互式终端`top`指令给出的信息含义一样。 #### Peek ![](/files/DdQQXmwf4NRhangdyb96) 相较于 Top 视图，增加了所属的上下文信息的展示，也就是函数的输出调用者/被调用者。 #### Source ![](/files/6OcJERgWNd8FvtezR2oi) 面向源代码的追踪和分析，可以看到主要开销在哪里。 ## pprof与benchmark基准测试结合使用 * -cpuprofile：cpu profiling 保存的文件路径 * -memprofile：memory profiling 保存的文件路径 * -blockprofile：block profiling 保存的文件路径 使用示例： ```bash go test -bench . -benchmem -cpuprofile=cpu.prof -memprofile=mem.prof -blockprofile=block.prof ``` 生成采集信息文件后，就跟上文中的分析方法一致了。 ## pprof与压力测试结合使用 ### 压测工具wrk 或 ### 使用步骤 1. 访问： 2. 启动压力测试：`go-wrk -n 50000 http://127.0.0.1:8080/version` 3. 点击 web 页面的 profile 按钮，收集信息，30 s 后会自动下载 profile 文件 4. 拿到 profile 文件后：`go tool pprof -http=":8081" profile` ## 优化案例 [以优化基准测试的lengthOfNonRepeatingSubStr函数为例](/golang/optimization/test.md) 1. 执行`go test -bench=Substr -v -cpuprofile=cpu.prof -benchmem`在性能测试的同时取得 CPU profiling 数据文件。 2. 执行`go tool pprof -http=":8081" cpu.prof`，访问`http://localhost:8081` ![初始](/files/-M_a6laIZiTyAjjdFWE3) 通过上图可以看出，大部分时间都花在了map相关操作 3. 知道了性能瓶颈所在之后，优化源代码，用`[]int`代替`map` ```go func lengthOfNonRepeatingSubStr1(s string) int { lastOccurred := make([]int, 0xffff) start := 0 maxLength := 0 for i, ch := range []rune(s) { if lastI := lastOccurred[ch]; lastI > start { start = lastI } if i-start+1 > maxLength { maxLength = i - start + 1 } lastOccurred[ch] = i + 1 } return maxLength } ``` 再执行测试命令： ```bash zhhnzw$ go test -bench=Substr -v -cpuprofile=cpu.prof -benchmem === RUN TestSubstr --- PASS: TestSubstr (0.00s) goos: darwin goarch: amd64 cpu: Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz BenchmarkSubstr nonrepeating_test.go:41: len(s) = 491520 nonrepeating_test.go:41: len(s) = 491520 nonrepeating_test.go:41: len(s) = 491520 BenchmarkSubstr-8 601 1968375 ns/op 1179663 B/op 2 allocs/op PASS ``` 可以看到，执行效率从`5152279 ns/op`进步到了`1968375 ns/op`，内存消耗从`655590 B/op`退步到了`1179663 B/op`，再执行`go tool pprof -http=":8081" cpu.prof`，访问`http://localhost:8081` ![优化后](/files/-M_a6laJVB9v8c7tplYT) 4. 可以看到，现在CPU性能消耗只剩下了`stringtoslicerune`，涉及到的就是`rune(s)`操作，这里是需要一个`utf-8`的解码操作耗费了CPU计算时间，因为必须要支持中文，这个解码操作是省不了的，所以CPU的优化到此就完成了。 5. 接下来再来看内存，观察到函数每次被调用每次都会创建一个`slice`，这一点可以优化，把`lastOccurred`变量提取到全局变量，在函数内每次都清掉它的值，这样这个`slice`变量就只用初始化一次了 ```go var lastOccurred = make([]int, 0xffff) func lengthOfNonRepeatingSubStr2(s string) int { for i,l:=0,len(lastOccurred);i start { start = lastI } if i-start+1 > maxLength { maxLength = i - start + 1 } lastOccurred[chs[i]] = i + 1 } return maxLength } ``` 再执行测试命令： ```bash zhhnzw$ go test -bench=Substr -v -cpuprofile=cpu.prof -benchmem === RUN TestSubstr --- PASS: TestSubstr (0.00s) goos: darwin goarch: amd64 cpu: Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz BenchmarkSubstr nonrepeating_test.go:41: len(s) = 491520 nonrepeating_test.go:41: len(s) = 491520 nonrepeating_test.go:41: len(s) = 491520 BenchmarkSubstr-8 620 1927372 ns/op 655362 B/op 1 allocs/op PASS ``` 可以看到，内存消耗进步到了`655362 B/op`，内存分配次数从2次优化到了1次，至此CPU和Memory都优化完毕了。