Profiling 是指在程序执行过程中，收集能够反映程序执行状态的数据。 在软件工程中，性能分析（performance analysis，也称为 profiling）， 是以收集程序运行时信息为手段研究程序行为的分析方法，是一种动态程序分析的方法。
什么是 pprof #
Go 语言自带的 pprof 库就可以分析程序的运行情况，并且提供可视化的功能。它包含两个相关的库：
- runtime/pprof 对于只跑一次的程序，例如每天只跑一次的离线预处理程序，调用 pprof 包提供的函数，手动开启性能数据采集。
- net/http/pprof 对于在线服务，对于一个 HTTP Server，访问 pprof 提供的 HTTP 接口，获得性能数据。 当然，实际上这里底层也是调用的 runtime/pprof 提供的函数，封装成接口对外提供网络访问。
pprof 的作用 #
下表来自 golang pprof 实战
| 类型 | 描述 | 备注 |
|---|---|---|
| allocs | 内存分配情况的采样信息 | 可以用浏览器打开，但可读性不高 |
| blocks | 阻塞操作情况的采样信息 | 可以用浏览器打开，但可读性不高 |
| cmdline | 当前程序的命令行调用 | 可以用浏览器打开，显示编译文件的临时目录 |
| goroutine | 当前所有协程的堆栈信息 | 可以用浏览器打开，但可读性不高 |
| heap | 堆上内存使用情况的采样信息 | 可以用浏览器打开，但可读性不高 |
| mutex | 锁争用情况的采样信息 | 可以用浏览器打开，但可读性不高 |
| profile | CPU 占用情况的采样信息 | 浏览器打开会下载文件 |
| threadcreate | 系统线程创建情况的采样信息 | 可以用浏览器打开，但可读性不高 |
| trace | 程序运行跟踪信息 | 浏览器打开会下载文件，本文不涉及，可另行参阅 深入浅出 Go trace |
allocs 和 heap 采样的信息一致，不过前者是所有对象的内存分配，而 heap 则是活跃对象的内存分配。
pprof 如何使用 #
我们可以通过报告生成、Web 可视化界面、交互式终端三种方式来使用 pprof。
runtime/pprof #
拿 CPU profiling 举例，增加两行代码，调用 pprof.StartCPUProfile 启动 cpu profiling，
调用 pprof.StopCPUProfile() 将数据刷到文件里：
package main
import "runtime/pprof"
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func main() {
// …
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
// …
}
net/http/pprof #
启动一个端口（和正常提供业务服务的端口不同）监听 pprof 请求：
package main
import (
"log"
"net/http"
_ "net/http/pprof"
"regexp"
)
func handler(wr http.ResponseWriter, r *http.Request) {
var pattern = regexp.MustCompile(`^(\w+)@foo.bar$`)
account := r.URL.Path[1:]
res := pattern.FindSubmatch([]byte(account))
if len(res) > 1 {
wr.Write(res[1])
} else {
wr.Write([]byte("None"))
}
}
func main() {
http.HandleFunc("/", handler)
err := http.ListenAndServe(":8888", nil)
if err != nil {
log.Fatal("ListenAndServe:", err)
}
}
pprof 包会自动注册 handler， 处理相关的请求：
// src/net/http/pprof/pprof.go:71
func init() {
http.Handle("/debug/pprof/", http.HandlerFunc(Index))
http.Handle("/debug/pprof/cmdline", http.HandlerFunc(Cmdline))
http.Handle("/debug/pprof/profile", http.HandlerFunc(Profile))
http.Handle("/debug/pprof/symbol", http.HandlerFunc(Symbol))
http.Handle("/debug/pprof/trace", http.HandlerFunc(Trace))
}
启动服务后，直接在浏览器访问：http://localhost:8888/debug/pprof/，得到如下页面：
关于 goroutine 的信息有两个链接，goroutine 和 full goroutine stack dump， 前者是一个汇总的消息，可以查看 goroutines 的总体情况， 后者则可以看到每一个 goroutine 的状态。 页面具体内容的解读可以参考大彬的文章 实战 Go 内存泄露。
采样分析 #
开始采样之前，需要模拟服务访问，这里用到的是压力测试管径 wrk。
# 启动 500 个 HTTP 连接，30 个线程，持续访问 1 分钟
wrk -c500 -t30 -d1m http://localhost:8888/zzz@foo.bar
报告生成 #
报告生成有 2 种方式：
- runtime/pprof 写入本地文件
- 内置页面下载采样文件
下面以内置页面为例： 在 debug/pprof 页面点击 profile，会在后台进行默认 30s 的数据采样，采样完成后，返回给浏览器一个采样文件，其他命令类似。 然后使用以下命令：
go tool pprof -http=:8080 profile
会在本地 8080 端口启动 http 服务，提供可视化界面：
图中的连线代表对方法的调用，连线上的标签代表指定的方法调用的采样值（例如时间、内存分配大小等）， 方框的大小与方法运行的采样值的大小有关。 每个方框由两个标签组成：在 cpu profile 中，一个是方法运行的时间占比， 一个是它在采样的堆栈中出现的时间占比（前者是 flat 时间，后者则是 cumulate 时间占比）； 框越大，代表耗时越多或是内存分配越多
点击左上角 VIEW 可以选择不同图形化展示，最常见的火焰图如下：
它和一般的火焰图相比刚好倒过来了，调用关系的展现是从上到下。形状越长，表示执行时间越长。
交互式命令 #
除了使用内置的页面采样分析，也直接使用如下命令，不需要通过浏览器直接进入~
# step1：压测工具访问服务
wrk -c500 -t30 -d1m http://localhost:8888/zzz@foo.bar
# step2：采集数据，默认 30s
go tool pprof http://localhost:8888/debug/pprof/profile
其他类似的采集数据命令还有：
# 自定义等待时间 120s
go tool pprof http://localhost:8888/debug/pprof/profile?second=120
# 下载 heap profile
go tool pprof http://localhost:8888/debug/pprof/heap
# 下载 goroutine profile
go tool pprof http://localhost:8888/debug/pprof/goroutine
# 下载 block profile
go tool pprof http://localhost:8888/debug/pprof/block
# 下载 mutex profile
go tool pprof http://localhost:8888/debug/pprof/mutex
下面开始进入命令行交互式模式，使用 top、list、web 等命令：
(pprof) top
Showing nodes accounting for 86.85s, 91.15% of 95.28s total
Dropped 397 nodes (cum <= 0.48s)
Showing top 10 nodes out of 93
flat flat% sum% cum cum%
75.37s 79.10% 79.10% 75.60s 79.35% syscall.syscall
3.79s 3.98% 83.08% 3.81s 4.00% runtime.kevent
1.52s 1.60% 84.68% 1.53s 1.61% runtime.usleep
1.21s 1.27% 85.95% 1.21s 1.27% runtime.pthread_cond_wait
1.20s 1.26% 87.21% 1.20s 1.26% runtime.pthread_kill
0.94s 0.99% 88.19% 0.94s 0.99% runtime.nanotime1
0.89s 0.93% 89.13% 0.89s 0.93% runtime.procyield
0.84s 0.88% 90.01% 0.84s 0.88% indexbytebody
0.59s 0.62% 90.63% 0.59s 0.62% runtime.pthread_cond_signal
0.50s 0.52% 91.15% 0.85s 0.89% runtime.scanobject
得到 5 列数据：
| 字段 | 描述 |
|---|---|
| flat | 本函数的执行耗时 |
| flat% | flat 占 CPU 总时间的比例。程序总耗时 95.28s，syscall.syscall 的 75.60s 占了 79.35% |
| sum% | 前面每一行的 flat 占比总和 |
| cum | 累计量。指该函数加上该函数调用的函数总耗时 |
| cum% | cum 占 CPU 总时间的比例 |
上面的结果没啥有价值的信息，都是 go 的底层调用。使用 list 正则匹配业务代码：
(pprof) list handler
Total: 1.65mins
ROUTINE ======================== main.handler in /Users/yuanhao/Study/GoProjects/testProject/pprof/main.go
30ms 2.63s (flat, cum) 2.65% of Total
. . 6: _ "net/http/pprof"
. . 7: "regexp"
. . 8:)
. . 9:
. . 10:func handler(wr http.ResponseWriter, r *http.Request) {
. 2.38s 11: var pattern = regexp.MustCompile(`^(\w+)@foo.bar$`)
20ms 20ms 12: account := r.URL.Path[1:]
. 160ms 13: res := pattern.FindSubmatch([]byte(account))
. . 14: if len(res) > 1 {
10ms 70ms 15: wr.Write(res[1])
. . 16: } else {
. . 17: wr.Write([]byte("None"))
. . 18: }
. . 19:}
. . 20:
ROUTINE ======================== net/http.(*ServeMux).handler in /usr/local/Cellar/go/1.15.1/libexec/src/net/http/server.go
10ms 10ms (flat, cum) 0.01% of Total
. . 2384: return mux.handler(host, r.URL.Path)
. . 2385:}
. . 2386:
. . 2387:// handler is the main implementation of Handler.
. . 2388:// The path is known to be in canonical form, except for CONNECT methods.
10ms 10ms 2389:func (mux *ServeMux) handler(host, path string) (h Handler, pattern string) {
. . 2390: mux.mu.RLock()
. . 2391: defer mux.mu.RUnlock()
. . 2392:
. . 2393: // Host-specific pattern takes precedence over generic ones
. . 2394: if mux.hosts {
可以看出，main.handler 总共用时 2.63s，其中 regexp.MustComplie 耗时 2.38ms。
罪魁祸首在这里：服务器每次收到请求，都要重新解析正则表达式。
进入下一步，使用 web 命令查看调用链，需要提前安装 graphviz 工具，自动调用浏览器展示下图：
图示与之前看到的调用链图基本一致，聚焦业务代码 main.handler，
可以发现regexp.Compile 耗时明显，因为每次请求过来，都要重新编译正则表达式。