# 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都优化完毕了。 --- # Agent Instructions: Querying This Documentation If you need additional information that is not directly available in this page, you can query the documentation dynamically by asking a question. Perform an HTTP GET request on the current page URL with the `ask` query parameter: ``` GET https://www.1024cx.top/golang/optimization/pprof.md?ask= ``` The question should be specific, self-contained, and written in natural language. The response will contain a direct answer to the question and relevant excerpts and sources from the documentation. Use this mechanism when the answer is not explicitly present in the current page, you need clarification or additional context, or you want to retrieve related documentation sections.