上QQ阅读APP看书，第一时间看更新
47.2 使用pprof进行性能剖析的实例
前面我们了解了go tool pprof的工作原理、性能数据类别、采样方式及剖析方式等，下面用一个实例来整体说明利用pprof进行性能剖析的过程。该示例改编自Brad Fitzpatrick在YAPC Asia 2015（http://yapcasia.org）上的一次名为“Go Debugging, Profiling, and Optimization”的技术分享。
1. 待优化程序（step0）
待优化程序是一个简单的HTTP服务，当通过浏览器访问其/hi服务端点时，页面上会显示如图47-9所示的内容。
图47-9 演示程序呈现的页面
页面上有一个计数器，显示访客是网站的第几个访客。该页面还支持通过color参数进行标题颜色定制，比如使用浏览器访问下面的地址后，页面显示的“Welcome!”标题将变成红色。
http://localhost:8080/hi?color=red
该待优化程序的源码如下：
//chapter8/sources/go-pprof-optimization-demo/step0/demo.go
var visitors int64
func handleHi(w http.ResponseWriter, r *http.Request) {
if match, _ := regexp.MatchString(`^\w*$`, r.FormValue("color")); !match {
http.Error(w, "Optional color is invalid", http.StatusBadRequest)
return
}
visitNum := atomic.AddInt64(&visitors, 1)
w.Header().Set("Content-Type", "text/html; charset=utf-8")
w.Write([]byte("<h1 style='color: " + r.FormValue("color") +
"'>Welcome!</h1>You are visitor number " + fmt.Sprint(visitNum) + "!"))
}
func main() {
log.Printf("Starting on port 8080")
http.HandleFunc("/hi", handleHi)
log.Fatal(http.ListenAndServe("127.0.0.1:8080", nil))
}
这里,我们的实验环境为Go 1.14 + macOS 10.14.6。
2. CPU类性能数据采样及数据剖析（step1）
前面提到go tool pprof支持多种类型的性能数据采集和剖析，在大多数情况下我们都会先从CPU类性能数据的剖析开始。这里通过为示例程序建立性能基准测试的方式采集CPU类性能数据。
// chapter8/sources/go-pprof-optimization-demo/step1/demo_test.go
...
func BenchmarkHi(b *testing.B) {
req, err := http.ReadRequest(bufio.NewReader(strings.NewReader("GET /hi HTTP/1.0\r\n\r\n")))
if err != nil {
b.Fatal(err)
}
rw := httptest.NewRecorder()
b.ResetTimer()
for i := 0; i < b.N; i++ {
handleHi(rw, req)
}
}
...
建立基准，取得初始基准测试数据：
$go test -v -run=^$ -bench=. goos: darwin goarch: amd64 pkg: chapter8/sources/go-pprof-optimization-demo/step1 BenchmarkHi BenchmarkHi-8 365084 3218 ns/op PASS ok chapter8/sources/go-pprof-optimization-demo/step1 2.069s
接下来，利用基准测试采样CPU类型性能数据：
$go test -v -run=^$ -bench=^BenchmarkHi$ -benchtime=2s -cpuprofile=cpu.prof
执行完上述命令后，step1目录下会出现两个新文件step1.test和cpu.prof。我们将这两个文件作为go tool pprof的输入对性能数据进行剖析：
$go tool pprof step1.test cpu.prof
File: step1.test
Type: cpu
Time: xx
Duration: 2.35s, Total samples = 2.31s (98.44%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top -cum
Showing nodes accounting for 0.18s, 7.79% of 2.31s total
Dropped 43 nodes (cum <= 0.01s)
Showing top 10 nodes out of 121
flat flat% sum% cum cum%
0 0% 0% 1.90s 82.25% chapter8/sources/go-pprof-optimization-demo/step1.BenchmarkHi
0 0% 0% 1.90s 82.25% chapter8/sources/go-pprof-optimization-demo/step1.handleHi
0 0% 0% 1.90s 82.25% testing.(*B).launch
0 0% 0% 1.90s 82.25% testing.(*B).runN
0 0% 0% 1.31s 56.71% regexp.MatchString
0 0% 0% 1.26s 54.55% regexp.Compile (inline)
0.01s 0.43% 0.43% 1.26s 54.55% regexp.compile
0.16s 6.93% 7.36% 0.75s 32.47% runtime.mallocgc
0.01s 0.43% 7.79% 0.49s 21.21% regexp/syntax.Parse
0 0% 7.79% 0.48s 20.78% bytes.(*Buffer).Write
(pprof)
通过top -cum，我们看到handleHi累积消耗CPU最多（用户层代码范畴）。通过list命令进一步展开handleHi函数：
(pprof) list handleHi
Total: 2.31s
ROUTINE ======================== chapter8/sources/go-pprof-optimization-demo/step1.handleHi in chapter8/sources/go-pprof-optimization-demo/step1/demo.go
0 1.90s (flat, cum) 82.25% of Total
. . 9:)
. . 10:
. . 11:var visitors int64 // must be accessed atomically
. . 12:
. . 13:func handleHi(w http.ResponseWriter, r *http.Request) {
. 1.31s 14:if match, _ := regexp.MatchString(`^\w*$`, r.FormValue
("color")); !match {
. . 15: http.Error(w, "Optional color is invalid",
http.StatusBadRequest)
. . 16: return
. . 17:}
. . 18:visitNum := atomic.AddInt64(&visitors, 1)
. 30ms 19:w.Header().Set("Content-Type", "text/html;
charset=utf-8")
. 500ms 20:w.Write([]byte("<h1 style='color: " + r.FormValue
("color") +
. 60ms 21: "'>Welcome!</h1>You are visitor number
" + fmt.Sprint(visitNum) + "!"))
. . 22:}
. . 23:
. . 24:func main() {
. . 25:log.Printf("Starting on port 8080")
. . 26:http.HandleFunc("/hi", handleHi)
(pprof)
我们看到在handleHi中，MatchString函数调用耗时最长（1.31s）。
3. 第一次优化（step2）
通过前面对CPU类性能数据的剖析，我们发现MatchString较为耗时。通过阅读代码发现，每次HTTP服务接收请求后，都会采用正则表达式对请求中的color参数值做一次匹配校验。校验使用的是regexp包的MatchString函数，该函数每次执行都要重新编译传入的正则表达式，因此速度较慢。我们的优化手段是：让正则表达式仅编译一次。下面是优化后的代码：
// chapter8/sources/go-pprof-optimization-demo/step2/demo.go
...
var visitors int64
var rxOptionalID = regexp.MustCompile(`^\d*$`)
func handleHi(w http.ResponseWriter, r *http.Request) {
if !rxOptionalID.MatchString(r.FormValue("color")) {
http.Error(w, "Optional color is invalid", http.StatusBadRequest)
return
}
...
}
...
在优化后的代码中，我们使用一个代表编译后正则表达式对象的rxOptionalID的MatchString方法替换掉了每次都需要重新编译正则表达式的MatchString函数调用。
重新运行一下性能基准测试：
$go test -v -run=^$ -bench=. goos: darwin goarch: amd64 pkg: chapter8/sources/go-pprof-optimization-demo/step2 BenchmarkHi BenchmarkHi-8 2624650 457 ns/op PASS ok chapter8/sources/go-pprof-optimization-demo/step2 1.734s
相比于优化前（3218 ns/op），优化后handleHi的性能（457 ns/op）提高了7倍多。
4. 内存分配采样数据剖析
在对待优化程序完成CPU类型性能数据剖析及优化实施之后，再来采集另一种常用的性能采样数据——内存分配类型数据，探索一下在内存分配方面是否还有优化空间。Go程序内存分配一旦过频过多，就会大幅增加Go GC的工作负荷，这不仅会增加GC所使用的CPU开销，还会导致GC延迟增大，从而影响应用的整体性能。因此，优化内存分配行为在一定程度上也是提升应用程序性能的手段。
在go-pprof-optimization-demo/step2目录下，为demo_test.go中的BenchmarkHi增加Report-Allocs方法调用，让其输出内存分配信息。然后，通过性能基准测试的执行获取内存分配采样数据：
$go test -v -run=^$ -bench=^BenchmarkHi$ -benchtime=2s -memprofile=mem.prof goos: darwin goarch: amd64 pkg: chapter8/sources/go-pprof-optimization-demo/step2 BenchmarkHi BenchmarkHi-8 5243474 455 ns/op 364 B/op 5 allocs/op PASS ok chapter8/sources/go-pprof-optimization-demo/step2 3.052s
接下来，使用pprof工具剖析输出的内存分配采用数据（mem.prof）：
$go tool pprof step2.test mem.prof File: step2.test Type: alloc_space Entering interactive mode (type "help" for commands, "o" for options) (pprof)
在go tool pprof的输出中有一行为Type: alloc_space。这行的含义是当前pprof将呈现程序运行期间所有内存分配的采样数据（即使该分配的内存在最后一次采样时已经被释放）。还可以让pprof将Type切换为inuse_space，这个类型表示内存数据采样结束时依然在用的内存。
可以在启动pprof工具时指定所使用的内存数据呈现类型：
$go tool pprof --alloc_space step2.test mem.prof // 遗留方式 $go tool pprof -sample_index=alloc_space step2.test mem.prof //最新方式
亦可在进入pprof交互模式后，通过sample_index命令实现切换：
(pprof) sample_index = inuse_space
现在以alloc_space类型进入pprof命令交互界面并执行top命令：
$go tool pprof -sample_index=alloc_space step2.test mem.prof
File: step2.test
Type: alloc_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top -cum
Showing nodes accounting for 2084.53MB, 99.45% of 2096.03MB total
Showing top 10 nodes out of 11
flat flat% sum% cum cum%
0 0% 0% 2096.03MB 100% chapter8/sources/go-pprof-optimization-
demo/step2.BenchmarkHi
840.55MB 40.10% 40.10% 2096.03MB 100% chapter8/sources/go-pprof-optimization-
demo/step2.handleHi
0 0% 40.10% 2096.03MB 100% testing.(*B).launch
0 0% 40.10% 2096.03MB 100% testing.(*B).runN
0 0% 40.10% 1148.98MB 54.82% bytes.(*Buffer).Write
0 0% 40.10% 1148.98MB 54.82% bytes.(*Buffer).grow
1148.98MB 54.82% 94.92% 1148.98MB 54.82% bytes.makeSlice
0 0% 94.92% 1148.98MB 54.82% net/http/httptest.(*ResponseRecorder).
Write
0 0% 94.92% 95MB 4.53% net/http.Header.Set (inline)
95MB 4.53% 99.45% 95MB 4.53% net/textproto.MIMEHeader.Set (inline)
(pprof)
我们看到handleHi分配了较多内存。通过list命令展开handleHi的代码：
(pprof) list handleHi
Total: 2.05GB
ROUTINE ======================== chapter8/sources/go-pprof-optimization-demo/step2.handleHi in chapter8/sources/go-pprof-optimization-demo/step2/demo.go
840.55MB 2.05GB (flat, cum) 100% of Total
. . 17: http.Error(w, "Optional color is invalid",
http.StatusBadRequest)
. . 18: return
. . 19: }
. . 20:
. . 21: visitNum := atomic.AddInt64(&visitors, 1)
. 95MB 22: w.Header().Set("Content-Type", "text/html;
charset= utf-8")
365.52MB 1.48GB 23: w.Write([]byte("<h1 style='color: " +
r.FormValue ("color") +
475.02MB 486.53MB 24: "'>Welcome!</h1>You are visitor number " +
fmt.Sprint(visitNum) + "!"))
. . 25:}
. . 26:
. . 27:func main() {
. . 28: log.Printf("Starting on port 8080")
. . 29: http.HandleFunc("/hi", handleHi)
(pprof)
通过list的输出结果我们可以看到handleHi函数的第23~25行分配了较多内存（见第一列）。
5. 第二次优化（step3）
这里进行内存分配的优化方法如下：
- 删除w.Header().Set这行调用；
- 使用fmt.Fprintf替代w.Write。
优化后的handleHi代码如下：
// go-pprof-optimization-demo/step3/demo.go
...
func handleHi(w http.ResponseWriter, r *http.Request) {
if !rxOptionalID.MatchString(r.FormValue("color")) {
http.Error(w, "Optional color is invalid", http.StatusBadRequest)
return
}
visitNum := atomic.AddInt64(&visitors, 1)
fmt.Fprintf(w, "<html><h1 stype='color: %s'>Welcome!</h1>You are visitor number %d!", r.FormValue("color"), visitNum)
}
...
再次执行性能基准测试来收集内存采样数据：
$go test -v -run=^$ -bench=^BenchmarkHi$ -benchtime=2s -memprofile=mem.prof goos: darwin goarch: amd64 pkg: github.com/bigwhite/books/effective-go/chapters/chapter8/sources/go-pprof-optimization-demo/step3 BenchmarkHi BenchmarkHi-8 7090537 346 ns/op 173 B/op 1 allocs/op PASS ok chapter8/sources/go-pprof-optimization-demo/step3 2.925s
和优化前的数据对比，内存分配次数由5 allocs/op降为1 allocs/op，每op分配的字节数由364B降为173B。
再次通过pprof对上面的内存采样数据进行分析，查看BenchmarkHi中的内存分配情况：
$go tool pprof step3.test mem.prof
File: step3.test
Type: alloc_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list handleHi
Total: 1.27GB
ROUTINE ======================== chapter8/sources/go-pprof-optimization-demo/step3.handleHi in chapter8/sources/go-pprof-optimization-demo/step3/demo.go
51.50MB 1.27GB (flat, cum) 100% of Total
. . 17: http.Error(w, "Optional color is invalid",
http. StatusBadRequest)
. . 18: return
. . 19: }
. . 20:
. . 21: visitNum := atomic.AddInt64(&visitors, 1)
51.50MB 1.27GB 22: fmt.Fprintf(w, "<html><h1 stype='color: %s'>Welcome!
</h1>You are visitor number %d!",
r.FormValue ("color"),visitNum)
. . 23:}
. . 24:
. . 25:func main() {
. . 26: log.Printf("Starting on port 8080")
. . 27: http.HandleFunc("/hi", handleHi)
(pprof)
我们看到，对比优化前handleHi的内存分配的确大幅减少（第一列：365MB+475MB -> 51.5MB）。
6. 零内存分配（step4）
经过一轮内存优化后，handleHi当前的内存分配集中到下面这行代码：
fmt.Fprintf(w, "<html><h1 stype='color: %s'>Welcome!</h1>You are visitor number %d!", r.FormValue("color"), visitNum)
fmt.Fprintf的原型如下：
$ go doc fmt.Fprintf
func Fprintf(w io.Writer, format string, a ...interface{}) (n int, err error)
我们看到Fprintf参数列表中的变长参数都是interface{}类型。前文曾提到过，一个接口类型占据两个字（word），在64位架构下，这两个字就是16字节。这意味着我们每次调用fmt.Fprintf，程序就要为每个变参分配一个占用16字节的接口类型变量，然后用传入的类型初始化该接口类型变量。这就是这行代码分配内存较多的原因。
要实现零内存分配，可以像下面这样优化代码：
// chapter8/sources/go-pprof-optimization-demo/step4/demo.go
...
var visitors int64 // 必须被自动访问
var rxOptionalID = regexp.MustCompile(`^\d*$`)
var bufPool = sync.Pool{
New: func() interface{} {
return bytes.NewBuffer(make([]byte, 128))
},
}
func handleHi(w http.ResponseWriter, r *http.Request) {
if !rxOptionalID.MatchString(r.FormValue("color")) {
http.Error(w, "Optional color is invalid", http.StatusBadRequest)
return
}
visitNum := atomic.AddInt64(&visitors, 1)
buf := bufPool.Get().(*bytes.Buffer)
defer bufPool.Put(buf)
buf.Reset()
buf.WriteString("<h1 style='color: ")
buf.WriteString(r.FormValue("color"))
buf.WriteString("'>Welcome!</h1>You are visitor number ")
b := strconv.AppendInt(buf.Bytes(), visitNum, 10)
b = append(b, '!')
w.Write(b)
}
这里有几点主要优化：
- 使用sync.Pool减少重新分配bytes.Buffer的次数；
- 采用预分配底层存储的bytes.Buffer拼接输出；
- 使用strconv.AppendInt将整型数拼接到bytes.Buffer中，strconv.AppendInt的实现如下：
// $GOROOT/src/strconv/itoa.go
func AppendInt(dst []byte, i int64, base int) []byte {
if fastSmalls && 0 <= i && i < nSmalls && base == 10 {
return append(dst, small(int(i))...)
}
dst, _ = formatBits(dst, uint64(i), base, i < 0, true)
return dst
}
我们看到AppendInt内置对十进制数的优化。对于我们的代码而言，这个优化的结果就是没有新分配内存，而是利用了传入的bytes.Buffer的实例，这样，代码中strconv.AppendInt的返回值变量b就是bytes.Buffer实例的底层存储切片。
运行一下最新优化后代码的性能基准测试并采样内存分配性能数据：
$go test -v -run=^$ -bench=^BenchmarkHi$ -benchtime=2s -memprofile=mem.prof goos: darwin goarch: amd64 pkg: chapter8/sources/go-pprof-optimization-demo/step4 BenchmarkHi BenchmarkHi-8 10765006 234 ns/op 199 B/op 0 allocs/op PASS ok chapter8/sources/go-pprof-optimization-demo/step4 2.884s
可以看到，上述性能基准测试的输出结果中每op的内存分配次数为0，而且程序性能也有了提升（346 ns/op → 234 ns/op）。剖析一下输出的内存采样数据：
$go tool pprof step4.test mem.prof
File: step4.test
Type: alloc_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list handleHi
Total: 2.12GB
ROUTINE ======================== chapter8/sources/go-pprof-optimization-demo/step4.handleHi in chapter8/sources/go-pprof-optimization-demo/step4/demo.go
0 2.12GB (flat, cum) 100% of Total
. . 33:buf.WriteString("<h1 style='color: ")
. . 34:buf.WriteString(r.FormValue("color"))
. . 35:buf.WriteString("'>Welcome!</h1>You are visitor
number ")
. . 36:b := strconv.AppendInt(buf.Bytes(), visitNum, 10)
. . 37:b = append(b, '!')
. 2.12GB 38:w.Write(b)
. . 39:}
. . 40:
. . 41:func main() {
. . 42:log.Printf("Starting on port 8080")
. . 43:http.HandleFunc("/hi", handleHi)
(pprof)
从handleHi代码展开的结果中已经看不到内存分配的数据了（第一列）。
7. 查看并发下的阻塞情况（step5）
前面进行的性能基准测试都是顺序执行的，无法反映出handleHi在并发下多个goroutine的阻塞情况，比如在某个处理环节等待时间过长等。为了了解并发下handleHi的表现，我们为它编写了一个并发性能基准测试：
// chapter8/sources/go-pprof-optimization-demo/step5/demo_test.go
...
func BenchmarkHiParallel(b *testing.B) {
r, err := http.ReadRequest(bufio.NewReader(strings.NewReader("GET /hi HTTP/1.0\r\n\r\n")))
if err != nil {
b.Fatal(err)
}
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
rw := httptest.NewRecorder()
for pb.Next() {
handleHi(rw, r)
}
})
}
...
执行该基准测试，并对阻塞时间类型数据（block.prof）进行采样与剖析：
$go test -bench=Parallel -blockprofile=block.prof
goos: darwin
goarch: amd64
pkg: chapter8/sources/go-pprof-optimization-demo/step5
BenchmarkHiParallel-8 15029988 118 ns/op
PASS
ok chapter8/sources/go-pprof-optimization-demo/step5 2.092s
$go tool pprof step5.test block.prof
File: step5.test
Type: delay
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3.70s, 100% of 3.70s total
Dropped 18 nodes (cum <= 0.02s)
Showing top 10 nodes out of 15
flat flat% sum% cum cum%
1.85s 50.02% 50.02% 1.85s 50.02% runtime.chanrecv1
1.85s 49.98% 100% 1.85s 49.98% sync.(*WaitGroup).Wait
0 0% 100% 1.85s 49.98% chapter8/sources/go-pprof-optimization-
demo/step5.BenchmarkHiParallel
0 0% 100% 1.85s 50.02% main.main
0 0% 100% 1.85s 50.02% runtime.main
0 0% 100% 1.85s 50.02% testing.(*B).Run
0 0% 100% 1.85s 49.98% testing.(*B).RunParallel
0 0% 100% 1.85s 50.01% testing.(*B).doBench
0 0% 100% 1.85s 49.98% testing.(*B).launch
0 0% 100% 1.85s 50.01% testing.(*B).run
(pprof) list handleHi
Total: 3.70s
ROUTINE ======================== chapter8/sources/go-pprof-optimization-demo/step5.handleHi in chapter8/sources/go-pprof-optimization-demo/step5/demo.go
0 18.78us (flat, cum) 0.00051% of Total
. . 19: return bytes.NewBuffer(make([]byte, 128))
. . 20: },
. . 21:}
. . 22:
. . 23:func handleHi(w http.ResponseWriter, r *http.Request) {
. 18.78us 24: if !rxOptionalID.MatchString(r.FormValue("color")) {
. . 25: http.Error(w, "Optional color is invalid",
http. StatusBadRequest)
. . 26: return
. . 27: }
. . 28:
. . 29: visitNum := atomic.AddInt64(&visitors, 1)
(pprof)
handleHi并未出现在top10排名中。进一步展开handleHi代码后，我们发现整个函数并没有阻塞goroutine过长时间的环节，因此无须对handleHi进行任何这方面的优化。当然这也源于Go标准库对regexp包的Regexp.MatchString方法做过针对并发的优化（也是采用sync.Pool），具体优化方法这里就不赘述了。
小结
在这一条中，我们学习了如何对Go程序进行性能剖析，讲解了使用pprof工具对Go应用进行性能剖析的原理、使用方法，并用一个示例演示了如何实施性能优化。
本条要点：
- 通过性能基准测试判定程序是否存在性能瓶颈，如存在，可通过Go工具链中的pprof对程序性能进行剖析；
- 性能剖析分为两个阶段——数据采集和数据剖析；
- go tool pprof工具支持多种数据采集方式，如通过性能基准测试输出采样结果和独立程序的性能数据采集；
- go tool pprof工具支持多种性能数据采样类型，如CPU类型（-cpuprofile）、堆内存分配类型（-memprofile）、锁竞争类型（-mutexprofile）、阻塞时间数据类型（-block-profile）等；
- go tool pprof支持两种主要的性能数据剖析方式，即命令行交互式和Web图形化方式；
- 在不明确瓶颈原因的情况下，应优先对CPU类型和堆内存分配类型性能采样数据进行剖析。