Demo 0
$ go tool pprof http://localhost:6060/debug/pprof/profile\?seconds\=60
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=60
Saved profile in /Users/weishi/pprof/pprof.samples.cpu.001.pb.gz
Type: cpu
Time: Aug 15, 2020 at 1:17pm (+08)
Duration: 1mins, Total samples = 2.95s ( 4.92%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 2810ms, 95.25% of 2950ms total
Dropped 11 nodes (cum <= 14.75ms)
Showing top 10 nodes out of 50
flat flat% sum% cum cum%
1610ms 54.58% 54.58% 1760ms 59.66% syscall.syscall
330ms 11.19% 65.76% 330ms 11.19% runtime.nanotime
210ms 7.12% 72.88% 210ms 7.12% runtime.usleep
160ms 5.42% 78.31% 310ms 10.51% runtime.notetsleep
150ms 5.08% 83.39% 150ms 5.08% runtime.exitsyscallfast
150ms 5.08% 88.47% 150ms 5.08% runtime.pthread_cond_timedwait_relative_np
100ms 3.39% 91.86% 100ms 3.39% runtime.memmove
40ms 1.36% 93.22% 40ms 1.36% runtime.pthread_cond_signal
30ms 1.02% 94.24% 60ms 2.03% runtime.findObject
30ms 1.02% 95.25% 30ms 1.02% runtime.spanOf
(pprof)
执行该命令后，需等待 60 秒（可调整 seconds 的值），pprof 会进行 CPU Profiling。结束后将默认进入 pprof 的交互式命令模式，可以对分析的结果进行查看或导出。
具体可执行 help 查看命令说明。
- flat：表示这个 function 本身执行花费的时间，不包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间
- flat%：表示这个 function 本身执行花费的时间在整个sampling中的比例，可以看出这个function执行的本身是否非常消耗CPU
- sum%：表示该 function 累积使用 CPU 耗时的总比例
- cum：表示这个function执行花费的总时间，即也包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间）
- cum%：表示这个function执行花费的总时间在整个sampling中的比例，可以看出调用这个function是否非常消耗CPU
使用 pdf (Outputs a graph in PDF format):
(pprof) pdf
Note that 我们需要安装 graphviz （brew install graphviz）。
输入 list <函数名称> 以查看占用较多CPU 的函数具体在哪：
Demo 1
我们写一个明显有问题的小demo，来看看我们怎么定位到问题源：
package main
import (
"net/http"
_ "net/http/pprof"
)
func main() {
go func() {
for {
stupidCall1()
}
}()
http.ListenAndServe("0.0.0.0:6060", nil)
}
func stupidCall1() {
stupidCall2()
}
func stupidCall2() {
for i := 0; i < 10000000000; i++ {
// do nothing
}
}
先启动程序，再运行：
$ go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /Users/weishi/pprof/pprof.samples.cpu.008.pb.gz
Type: cpu
Time: Aug 15, 2020 at 4:26pm (+08)
Duration: 30.10s, Total samples = 26.32s (87.44%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top5
Showing nodes accounting for 26300ms, 99.92% of 26320ms total
Dropped 4 nodes (cum <= 131.60ms)
Showing top 5 nodes out of 7
flat flat% sum% cum cum%
25900ms 98.40% 98.40% 25900ms 98.40% main.stupidCall2
400ms 1.52% 99.92% 400ms 1.52% runtime.nanotime
0 0% 99.92% 25900ms 98.40% main.main.func1
0 0% 99.92% 25900ms 98.40% main.stupidCall1
0 0% 99.92% 410ms 1.56% runtime.mstart
(pprof) list stupid
Total: 26.32s
ROUTINE ======================== main.stupidCall1 in /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go
0 25.90s (flat, cum) 98.40% of Total
. . 14:
. . 15: http.ListenAndServe("0.0.0.0:6060", nil)
. . 16:}
. . 17:
. . 18:func stupidCall1() {
. 25.90s 19: stupidCall2()
. . 20:}
. . 21:
. . 22:func stupidCall2() {
. . 23: for i := 0; i < 10000000000; i++ {
. . 24: // do nothing
ROUTINE ======================== main.stupidCall2 in /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go
25.90s 25.90s (flat, cum) 98.40% of Total
. . 18:func stupidCall1() {
. . 19: stupidCall2()
. . 20:}
. . 21:
. . 22:func stupidCall2() {
25.90s 25.90s 23: for i := 0; i < 10000000000; i++ {
. . 24: // do nothing
. . 25: }
. . 26:}
(pprof)
可以看到，我们成功定位到了问题（sample 时间为26.32s，问题代码花了25.90s，98.40%）。
我们再试着生成PDF：
(pprof) pdf
Generating report in profile002.pdf
Demo 2
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
)
func main() {
go func() {
for {
swTest()
}
}()
fmt.Println("start api server...")
panic(http.ListenAndServe(":8080", nil))
}
func swTest() {
for i := 0; i < 1000000; i++ {
// do nothing
}
stupidCall1()
stupidCall2()
}
func stupidCall1() {
//minorF()
//fib1(10000000)
for i := 0; i < 1000000; i++ {
// do nothing
}
}
func stupidCall2() {
//minorF()
//fib1(10000000)
for i := 0; i < 1000000; i++ {
// do nothing
}
}
可以看到，在 swTest ， stupidCall1 和 stupidCall2 中，都会执行一个空的 for 循环 1000000 次。因此，在这三个部分执行所花的时间应该大致相同。
事实上，确实是相同的，分别是 0.55m、0.59m 和 0.57m。
因此，function_name duration_A of duration_B 表示：
duration_A表示function_name本身执行花费的总时间（不包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间）duration_B表示function_name执行花费的总时间，即也包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间）
因此，满足 0.59+0.57+0.06+0.55m <= 1.77m，因为有一些节点如果耗时非常少，则会被忽略。
Graph
Top
- Flat：表示这个 function 本身执行花费的时间，不包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间
- Flat%：表示这个 function 本身执行花费的时间在整个sampling中的比例，可以看出这个function执行的本身是否非常消耗CPU
- Sum%：
- Cum：表示这个function执行花费的总时间，即也包括这个function 在内部调用其他 function 且在执行这些其他 function时所花费的时间）
- Cum%：表示这个function执行花费的总时间在整个sampling中的比例，可以看出调用这个function是否非常消耗CPU
Flame Graph
Peek
Type: cpu
Time: Sep 12, 2020 at 12:34pm (+08)
Duration: 30.19s, Total samples = 26.80s (88.76%)
Showing nodes accounting for 26.80s, 100% of 26.80s total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
8.57s 100% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:27
8.57s 31.98% 31.98% 8.57s 31.98% | main.stupidCall2 /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:40
----------------------------------------------------------+-------------
8.42s 100% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:25
8.42s 31.42% 63.40% 8.42s 31.42% | main.stupidCall1 /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:32
----------------------------------------------------------+-------------
8.21s 100% | main.main.func1 /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:12
8.21s 30.63% 94.03% 8.21s 30.63% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:21
这说明：
- 执行
sw_pprof.go:27处花费了 8.57s，其中sw_pprof.go:27其实会向下调用stupidCall2，而在这个 function 中sw_pprof.go:40花费了 8.57s sw_pprof.go:25和sw_pprof.go:12也是类似
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
0 0% 100% 26.28s 98.06% | main.main.func1 /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:12
8.57s 32.61% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:27
8.42s 32.04% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:25
8.21s 31.24% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:21
1.08s 4.11% | main.swTest /Users/weishi/Working/GoPlayground/sw_pprof/sw_pprof.go:20
在 sw_pprof.go:12花费了 98.06%的时间，在这个function内部，时间分别花在了 sw_pprof.go:27、sw_pprof.go:25、sw_pprof.go:21 和 sw_pprof.go:20，分别占用了32.61%、32.04%、31.24% 和 4.11%。
Source
可以非常直观的看到消耗较多CPU的代码位置：
Reference
- https://golang.org/pkg/net/http/pprof/
- https://blog.golang.org/pprof
- https://golang.org/pkg/runtime/pprof/
- https://github.com/google/pprof/blob/master/doc/README.md
- https://blog.wolfogre.com/posts/go-ppof-practice/