go性能分析 及 线上问题定位
医生的温度计、听诊器、血压计，可以获取就诊者的各种健康指标。
如果把研发工程师比喻成医生，那pprof就是类似温度计、听诊器、血压计的一个工具集，可以用来分析CPU、goroutine堆栈跟踪、内存分配及使用情况、互斥锁争用及耗时、goroutine阻塞 等
(1) pprof是什么
性能分析是通过分析器(profiler)工具进行检测来实现的，在 Go 中使用称为 pprof。
pprof工具可以用来监测进程的运行数据，用于监控程序的性能及状况，以下指标都可以监控
CPU— 确定应用程序的时间花在了哪里
Goroutine— 报告正在运行的 goroutines 堆栈跟踪
Heap— 报告堆内存分配以监视当前内存使用情况并检查可能的内存泄漏
Mutex— 报告锁争情况来分析代码中互斥锁使用行为以及应用程序是否在锁定调用上花费了太多时间
Block— 显示 goroutines 阻塞等待同步原语的位置
(2) 如何使用pprof
pprof必须在代码里引入才能使用
不像Java里的 jps、jstat、jinfo、jstack、jmap 工具可以单独使用
pprof 可以从以下两个包中引入
import "net/http/pprof"
import "runtime/pprof" 其中 net/http/pprof 使用 runtime/pprof 包来进行封装，并在 http 端口上暴露出来。
runtime/pprof 可以用来产生 dump 文件，再使用 go tool pprof 来分析这运行日志。
使用 net/http/pprof 可以做到直接看到当前 web 服务的状态，包括 CPU 占用情况和内存使用情况等。
(2.1) 通过网页可视化使用pprof
import (
"net/http"
// 代码里引入 pprof
_ "net/http/pprof"
)
func main() {
// 代码里引入http server
go func() {
if err := http.ListenAndServe(":6060", nil); err != nil {
log.Fatal(err)
}
os.Exit(0)
}()
// 省略业务代码
}
导入 net/http/pprof 的作用是，我们可以通过 http://127.0.0.1:6060/debug/pprof/ 来访问 pprof
通过 这个地址 可以通过网页很方便的查看各项指标
即使在生产环境中启用 pprof 也是安全的
| 作用 | 关键字 | 访问url |
|---|---|---|
| 所有过去内存分配的样本 | allocs | http://127.0.0.1:6060/debug/pprof/allocs?debug=1 |
| 导致同步基元阻塞的堆栈跟踪 | block | http://127.0.0.1:6060/debug/pprof/block?debug=1 |
| 当前程序的命令行调用 | cmdline | |
| 所有当前 goroutines 的堆栈跟踪 | goroutine | http://127.0.0.1:6060/debug/pprof/goroutine?debug=1 |
| 活动对象的内存分配示例 | heap | http://127.0.0.1:6060/debug/pprof/heap?debug=1 |
| 争用互斥锁持有者的堆栈跟踪 | mutx | http://127.0.0.1:6060/debug/pprof/mutex?debug=1 |
| CPU性能分析 | profile | http://127.0.0.1:6060/debug/pprof/profile?debug=1 |
| 创建新操作系统线程的堆栈跟踪 | threadcreate | http://127.0.0.1:6060/debug/pprof/threadcreate?debug=1 |
| 当前程序执行的跟踪 | full goroutine stack dump | http://127.0.0.1:6060/debug/pprof/goroutine?debug=2 |
(2.2) 通过下载的pprof文件分析
(2.2.1) 下载并使用
直接运行 go tool pprof http://localhost:6060/debug/pprof/profile，其会自动下载数据到本地，然后供分析。
默认会下载到当前用户的 ~/pprof/pprof.samples.cpu.001.pb.gz 目录下
go tool pprof http://localhost:6060/debug/pprof/profile = download filepath + go tool pprof filepath
[weikeqin@bogon thrift-tutorial-go-demo (master)]$ go tool pprof http://localhost:6060/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile
Saved profile in /Users/weikeqin/pprof/pprof.samples.cpu.001.pb.gz
Type: cpu
Time: Aug 20, 2022 at 8:37pm (CST)
Duration: 30s, Total samples = 2.37s ( 7.90%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) (2.2.2) 下载数据离线分析
下载文件
[weikeqin@computer ~]$ curl -o /Users/weikeqin/pprof/go_profile.out http://localhost:6060/debug/pprof/profile
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 107 100 107 0 0 3 0 0:00:35 0:00:30 0:00:05 22
[weikeqin@computer ~]$ 执行 curl -o /Users/weikeqin/pprof/go_profile.out http://localhost:6060/debug/pprof/profile ，会下载原始数据文件到 /Users/weikeqin/pprof/go_profile.out 目录。
分析文件
[weikeqin@computer pprof]$ go tool pprof /Users/weikeqin/pprof/go_profile.out
Type: cpu
Time: Aug 20, 2022 at 3:39pm (CST)
Duration: 30.01s, Total samples = 0
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)(3) 分析CPU占用情况
通过 http://127.0.0.1:6060/debug/pprof/profile?debug=1 可以下载 go_pprof_profile.out 文件
(3.1) CPU分析原理
CPU 分析器依赖于操作系统和信号。
当它被激活时，应用程序默认通过 SIGPROF 信号要求操作系统每 10 毫秒中断一次。当应用程序收到 SIGPROF 时，它会暂停当前活动并将执行转移到分析器。
分析器收集诸如当前 goroutine 活动之类的数据，并汇总可以检索的执行统计信息；然后停止分析并继续执行直到下一次的 SIGPROF。
我们可以访问 /debug/pprof/profile 路由来激活 CPU 分析。默认情况下，访问此路由会执行 30 秒的 CPU 分析。在 30 秒内，我们的应用程序每 10 毫秒中断一次。
请注意，可以更改这两个默认值：使用 seconds 参数将分析应该持续多长时间传递给路由（例如 /debug/pprof/profile?seconds=15），也可以更改中断率（甚至小于 10 毫秒）。
但多数情况下，10 毫秒应该足够了，在减小这个值（意味着增加频率）时，我们应该注意不要对性能产生影响。30 秒后，就可以下载 CPU 分析器的结果。
注意：
也可以通过 -cpuprofile 标志来开启 CPU 分析器，比如在运行基准测试时就可以用这种方式。
例如，执行以下命令后可通过 /debug/pprof/profile 下载到相同的分析结果文件。
(3.2) 通过命令分析CPU数值指标
如果在代码里使用了 http.ListenAndServe(":6060", nil)，可以直接访问 http://127.0.0.1:6060/debug/pprof/profile?debug=1 获取profile文件
获取profile文件后使用 go tool pprof go_profile.out 来分析CPU占用情况
(pprof)
(pprof) help
Commands:
callgrind Outputs a graph in callgrind format
comments Output all profile comments
disasm Output assembly listings annotated with samples
dot Outputs a graph in DOT format
eog Visualize graph through eog
evince Visualize graph through evince
gif Outputs a graph image in GIF format
gv Visualize graph through gv
kcachegrind Visualize report in KCachegrind
list Output annotated source for functions matching regexp
pdf Outputs a graph in PDF format
peek Output callers/callees of functions matching regexp
png Outputs a graph image in PNG format
proto Outputs the profile in compressed protobuf format
ps Outputs a graph in PS format
raw Outputs a text representation of the raw profile
svg Outputs a graph in SVG format
tags Outputs all tags in the profile
text Outputs top entries in text form
top Outputs top entries in text form
topproto Outputs top entries in compressed protobuf format
traces Outputs all profile samples in text form
tree Outputs a text rendering of call graph
web Visualize graph through web browser
weblist Display annotated source in a web browser
o/options List options and their current values
q/quit/exit/^D Exit pprof
Options:
call_tree Create a context-sensitive call tree
compact_labels Show minimal headers
divide_by Ratio to divide all samples before visualization
drop_negative Ignore negative differences
edgefraction Hide edges below <f>*total
focus Restricts to samples going through a node matching regexp
hide Skips nodes matching regexp
ignore Skips paths going through any nodes matching regexp
intel_syntax Show assembly in Intel syntax
mean Average sample value over first value (count)
nodecount Max number of nodes to show
nodefraction Hide nodes below <f>*total
noinlines Ignore inlines.
normalize Scales profile based on the base profile.
output Output filename for file-based outputs
prune_from Drops any functions below the matched frame.
relative_percentages Show percentages relative to focused subgraph
sample_index Sample value to report (0-based index or name)
show Only show nodes matching regexp
show_from Drops functions above the highest matched frame.
source_path Search path for source files
tagfocus Restricts to samples with tags in range or matched by regexp
taghide Skip tags matching this regexp
tagignore Discard samples with tags in range or matched by regexp
tagleaf Adds pseudo stack frames for labels key/value pairs at the callstack leaf.
tagroot Adds pseudo stack frames for labels key/value pairs at the callstack root.
tagshow Only consider tags matching this regexp
trim Honor nodefraction/edgefraction/nodecount defaults
trim_path Path to trim from source paths before search
unit Measurement units to display
Option groups (only set one per group):
granularity
functions Aggregate at the function level.
filefunctions Aggregate at the function level.
files Aggregate at the file level.
lines Aggregate at the source code line level.
addresses Aggregate at the address level.
sort
cum Sort entries based on cumulative weight
flat Sort entries based on own weight
: Clear focus/ignore/hide/tagfocus/tagignore
type "help <cmd|option>" for more information
(pprof)
(pprof) (3.2.1) 生成调用关系图
(pprof) web
(pprof) 会生成一个svg图片保存到 file:///private/var/folders/ry/j30lp1sn19q7rbtq6020f6880000gn/T/pprof001.svg，并且自动打开。
每个方框代表一个函数，方框的大小和执行时间成正比，箭头代表调用关系，箭头上的时间代表被调用函数的执行时间
(3.2.2) 查看top占用
(pprof) top
Showing nodes accounting for 5.75s, 94.73% of 6.07s total
Dropped 118 nodes (cum <= 0.03s)
Showing top 10 nodes out of 94
flat flat% sum% cum cum%
3.46s 57.00% 57.00% 3.47s 57.17% syscall.syscall6
1.34s 22.08% 79.08% 1.34s 22.08% runtime.kevent
0.30s 4.94% 84.02% 0.30s 4.94% syscall.syscall
0.16s 2.64% 86.66% 0.16s 2.64% runtime.siftdownTimer
0.12s 1.98% 88.63% 0.13s 2.14% runtime.chansend
0.12s 1.98% 90.61% 0.14s 2.31% runtime.walltime
0.10s 1.65% 92.26% 0.10s 1.65% runtime.madvise
0.08s 1.32% 93.57% 0.08s 1.32% runtime.memclrNoHeapPointers
0.06s 0.99% 94.56% 0.06s 0.99% runtime.nanotime1
0.01s 0.16% 94.73% 0.16s 2.64% runtime.mallocgc
(pprof)(3.3) CPU参数页面可视化分析
如果通过 go tool pprof go_profile.out 分析时觉得数字不直观时，可以通过页面可视化来查看
其实就是开了一个http服务，然后把 go_profile.out 做成可视化的了
比如 go_profile.out 对应的路径是 /Users/weikeqin/WorkSpaces/golang/go_profile.out
[weikeqin@computer ~]$ go tool pprof -http=:8080 /Users/weikeqin/WorkSpaces/golang/go_profile.out
Serving web UI on http://localhost:8080 
(3.3.1) 调用链路(graph)
(3.3.2) 火焰图(flamegraph)
(3.3.3) top
CPU top占用情况
(3.4) 分析后的收获
对 runtime.mallogc 的调用过多，意味着我们可以尝试减少过多的小堆分配
在通道操作或互斥锁上花费太多时间，可能表明过度竞争正在损害应用程序的性能
在 syscall.Read 或 syscall.Write 上花费太多时间，意味着应用程序在内核模式下花费了大量时间。处理 I/O 缓冲可能是改进的途径
(4) 分析内存-堆占用情况
通过 http://127.0.0.1:6060/debug/pprof/heap?debug=1 可以查看堆占用情况
(4.1) 堆分析原理
与 CPU 分析一样，堆分析也是基于采样的。
(4.2) 分析堆占用数字指标
通过 http://127.0.0.1:6060/debug/pprof/heap?debug=1 可以获取堆占用的详细数字指标
(4.3) 通过工具分析
[weikeqin@computer pprof]$ go tool pprof /Users/weikeqin/pprof/go_pprof_heap.out
Type: inuse_space
Time: Aug 20, 2022 at 4:29pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)(pprof) svg
Generating report in profile001.svg
(pprof)生成svg，查看堆占用情况
(4.3) 通过网页可视化分析
通过 http://127.0.0.1:6060/debug/pprof/heap?debug=0 下载文件，下载的文件可以重名名
[weikeqin@bogon ~]$ go tool pprof -http=:8082 /Users/weikeqin/pprof/go_pprof_heap.out
Serving web UI on http://localhost:8082 
alloc_objects— 分配的对象总数
alloc_space— 分配的内存总量
inuse_objects— 已分配但尚未释放的对象数
inuse_space— 已分配但尚未释放的内存量
(5) 遇到的问题
(5.1) Could not execute dot; may need to install graphviz.
[weikeqin@bogon thrift-tutorial-go-demo (master)]$ go tool pprof -http=:8080 /Users/weikeqin/WorkSpaces/golang/go_profile.out
Serving web UI on http://localhost:8080
Failed to execute dot. Is Graphviz installed?
exec: "dot": executable file not found in $PATH
Failed to execute dot. Is Graphviz installed?
exec: "dot": executable file not found in $PATH
到 https://www.graphviz.org/download/ 下载 Graphviz
参考资料
[1] 如何排查 Go 程序 CPU 占用过高问题
[2] Go 程序内存泄露问题快速定位
[3] golang pprof 实战 △
[4] 实用go pprof使用指南
[5] Go 中的性能分析和执行跟踪 ☆
[6] go.dev-doc-diagnostics#profiling
[7] 使用google的pprof工具以及在gin中集成pprof
[8] Golang性能测试工具PProf应用详解
[9] Concurrency isn’t Always Faster in Go