Go 博客
Go 程序性能分析
在 2011 年的 Scala Days 会议上，Robert Hundt 发表了一篇题为 Loop Recognition in C++/Java/Go/Scala 的论文。这篇论文用 C++、Go、Java、Scala 实现了特定的循环查找算法（例如您在编译器流分析阶段可能使用的算法），然后使用这些程序来得出关于这些语言中典型性能问题的结论。论文中提到的 Go 程序运行非常缓慢，这为演示如何使用 Go 的性能分析工具来优化慢速程序提供了绝佳机会。
通过使用 Go 的性能分析工具识别和纠正特定瓶颈，我们可以使 Go 的循环查找程序运行速度提高一个数量级，并减少 6 倍的内存使用。（更新：由于最近 gcc 中 libstdc++ 的优化，内存减少量现在是 3.7 倍。）
Hundt 的论文没有具体说明他使用了哪些版本的 C++、Go、Java 和 Scala 工具。在这篇博文中，我们将使用 6g Go 编译器的最新每周快照以及 Ubuntu Natty 发行版附带的 g++ 版本。（我们不会使用 Java 或 Scala，因为我们不擅长用这两种语言编写高效程序，所以比较会不公平。由于 C++ 在论文中是最快的语言，这里与 C++ 的比较应该足够了。）（更新：在这篇更新的博文中，我们将使用 amd64 上 Go 编译器的最新开发快照以及最新版本的 g++ – 4.8.0，该版本于 2013 年 3 月发布。）
$ go version
go version devel +08d20469cc20 Tue Mar 26 08:27:18 2013 +0100 linux/amd64
$ g++ --version
g++ (GCC) 4.8.0
Copyright (C) 2013 Free Software Foundation, Inc.
...
$
这些程序运行在一台配备 3.4GHz Core i7-2600 CPU 和 16 GB 内存、运行 Gentoo Linux 3.8.4-gentoo 内核的计算机上。机器通过以下方式禁用了 CPU 频率缩放：
$ sudo bash
# for i in /sys/devices/system/cpu/cpu[0-7]
do
echo performance > $i/cpufreq/scaling_governor
done
#
我们选取了 Hundt 的 C++ 和 Go 基准测试程序，将它们合并到单个源文件中，并删除了除一行输出之外的所有内容。我们将使用 Linux 的 time 工具以显示用户时间、系统时间、实际时间和最大内存使用量的格式来测量程序运行时间。
$ cat xtime
#!/bin/sh
/usr/bin/time -f '%Uu %Ss %er %MkB %C' "$@"
$
$ make havlak1cc
g++ -O3 -o havlak1cc havlak1.cc
$ ./xtime ./havlak1cc
# of loops: 76002 (total 3800100)
loop-0, nest: 0, depth: 0
17.70u 0.05s 17.80r 715472kB ./havlak1cc
$
$ make havlak1
go build havlak1.go
$ ./xtime ./havlak1
# of loops: 76000 (including 1 artificial root node)
25.05u 0.11s 25.20r 1334032kB ./havlak1
$
C++ 程序在 17.80 秒内运行完成，使用 700 MB 内存。Go 程序在 25.20 秒内运行完成，使用 1302 MB 内存。（这些测量结果与论文中的结果难以吻合，但这篇博文的重点是探讨如何使用 go tool pprof，而不是重现论文中的结果。）
要开始调优 Go 程序，我们必须启用性能分析。如果代码使用了 Go testing 包的基准测试支持，我们可以使用 gotest 标准的 -cpuprofile 和 -memprofile 标志。对于像这样的独立程序，我们必须导入 runtime/pprof 并添加几行代码：
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func main() {
flag.Parse()
if *cpuprofile != "" {
f, err := os.Create(*cpuprofile)
if err != nil {
log.Fatal(err)
}
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
}
...
新代码定义了一个名为 cpuprofile 的标志，调用 Go flag 库解析命令行标志，然后，如果在命令行上设置了 cpuprofile 标志，则 启动 CPU 性能分析并重定向到指定文件。性能分析器需要在程序退出前最后调用 StopCPUProfile 以将所有待写入内容刷新到文件；我们使用 defer 来确保在 main 返回时执行此操作。
添加这段代码后，我们可以使用新的 -cpuprofile 标志运行程序，然后运行 go tool pprof 来解释性能分析结果。
$ make havlak1.prof
./havlak1 -cpuprofile=havlak1.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak1 havlak1.prof
Welcome to pprof! For help, type 'help'.
(pprof)
go tool pprof 程序是 Google 的 pprof C++ 性能分析器的一个稍作修改的版本。最重要的命令是 topN，它显示性能分析中前 N 个样本的数据：
(pprof) top10
Total: 2525 samples
298 11.8% 11.8% 345 13.7% runtime.mapaccess1_fast64
268 10.6% 22.4% 2124 84.1% main.FindLoops
251 9.9% 32.4% 451 17.9% scanblock
178 7.0% 39.4% 351 13.9% hash_insert
131 5.2% 44.6% 158 6.3% sweepspan
119 4.7% 49.3% 350 13.9% main.DFS
96 3.8% 53.1% 98 3.9% flushptrbuf
95 3.8% 56.9% 95 3.8% runtime.aeshash64
95 3.8% 60.6% 101 4.0% runtime.settype_flush
88 3.5% 64.1% 988 39.1% runtime.mallocgc
启用 CPU 性能分析时，Go 程序每秒停止约 100 次，并记录一个样本，该样本包含当前执行的 goroutine 堆栈上的程序计数器。该性能分析有 2525 个样本，因此程序运行了略多于 25 秒。在 go tool pprof 的输出中，每个出现在样本中的函数都有一行数据。前两列显示了函数正在运行（而不是等待被调用函数返回）的样本数量，分别以原始计数和总样本百分比表示。runtime.mapaccess1_fast64 函数在 298 个样本中运行，占 11.8%。top10 输出按此样本计数排序。第三列显示列表中的累积总数：前三行占总样本的 32.4%。第四和第五列显示函数出现在样本中的数量（无论是正在运行还是等待被调用的函数返回）。main.FindLoops 函数在 10.6% 的样本中运行，但在 84.1% 的样本中位于调用堆栈上（它或它调用的函数正在运行）。
要按第四和第五列排序，请使用 -cum（累计）标志：
(pprof) top5 -cum
Total: 2525 samples
0 0.0% 0.0% 2144 84.9% gosched0
0 0.0% 0.0% 2144 84.9% main.main
0 0.0% 0.0% 2144 84.9% runtime.main
0 0.0% 0.0% 2124 84.1% main.FindHavlakLoops
268 10.6% 10.6% 2124 84.1% main.FindLoops
(pprof) top5 -cum
实际上，main.FindLoops 和 main.main 的总数应该是 100%，但每个堆栈样本仅包含底部 100 个堆栈帧；在大约四分之一的样本中，递归的 main.DFS 函数比 main.main 深 100 帧以上，因此完整的调用栈被截断了。
堆栈跟踪样本包含比文本列表能显示的更有趣的函数调用关系数据。web 命令将性能分析数据以 SVG 格式绘制成图并使用网络浏览器打开。（还有一个 gv 命令可以生成 PostScript 格式并使用 Ghostview 打开。对于这两个命令，您都需要安装 graphviz。）
(pprof) web
完整图的一小部分如下所示：
图中的每个框对应一个函数，框的大小根据函数正在运行的样本数量确定。从框 X 到框 Y 的边表示 X 调用了 Y；沿边上的数字表示该调用在样本中出现的次数。如果一个调用在单个样本中出现多次，例如在递归函数调用期间，每次出现都计入边的权重。这解释了从 main.DFS 到自身的自循环边上的数字 21342。
仅凭一眼，我们就可以看出程序大部分时间花在哈希操作上，这对应于 Go 的 map 值的使用。我们可以告诉 web 只使用包含特定函数的样本，例如 runtime.mapaccess1_fast64，这可以清除图中的一些干扰信息：
(pprof) web mapaccess1
如果我们仔细看，可以看到对 runtime.mapaccess1_fast64 的调用是由 main.FindLoops 和 main.DFS 发出的。
现在我们对全局有了一个大致了解，是时候聚焦于某个特定函数了。我们先看看 main.DFS，仅仅因为它是一个较短的函数：
(pprof) list DFS
Total: 2525 samples
ROUTINE ====================== main.DFS in /home/rsc/g/benchgraffiti/havlak/havlak1.go
119 697 Total samples (flat / cumulative)
3 3 240: func DFS(currentNode *BasicBlock, nodes []*UnionFindNode, number map[*BasicBlock]int, last []int, current int) int {
1 1 241: nodes[current].Init(currentNode, current)
1 37 242: number[currentNode] = current
. . 243:
1 1 244: lastid := current
89 89 245: for _, target := range currentNode.OutEdges {
9 152 246: if number[target] == unvisited {
7 354 247: lastid = DFS(target, nodes, number, last, lastid+1)
. . 248: }
. . 249: }
7 59 250: last[number[currentNode]] = lastid
1 1 251: return lastid
(pprof)
列表显示了 DFS 函数（实际上是匹配正则表达式 DFS 的所有函数）的源代码。前三列分别是该行代码执行时采集到的样本数、该行代码或由其调用的代码执行时采集到的样本数以及文件中的行号。相关的命令 disasm 显示的是函数的反汇编而不是源代码列表；当有足够的样本时，这可以帮助您了解哪些指令开销较大。weblist 命令结合了这两种模式：它显示 一个源代码列表，点击一行可以显示相应的反汇编。
既然我们已经知道时间主要花在哈希运行时函数实现的 map 查找上，我们最关心的是第二列。相当大一部分时间花在对 DFS 的递归调用上（第 247 行），这在递归遍历中是可以预料的。排除递归之外，看起来时间花在了第 242、246 和 250 行对 number map 的访问上。对于这种特定的查找，map 不是最高效的选择。就像在编译器中一样，基本块结构被分配了唯一的序列号。与其使用 map[*BasicBlock]int，我们可以使用 []int，一个通过块编号索引的切片。当可以使用数组或切片时，没有理由使用 map。
将 number 从 map 改为切片需要在程序中修改七行代码，这将使其运行时间减少近一半：
$ make havlak2
go build havlak2.go
$ ./xtime ./havlak2
# of loops: 76000 (including 1 artificial root node)
16.55u 0.11s 16.69r 1321008kB ./havlak2
$
（参见 havlak1 和 havlak2 之间的 diff）
我们可以再次运行性能分析器以确认 main.DFS 不再占用大量运行时间：
$ make havlak2.prof
./havlak2 -cpuprofile=havlak2.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak2 havlak2.prof
Welcome to pprof! For help, type 'help'.
(pprof)
(pprof) top5
Total: 1652 samples
197 11.9% 11.9% 382 23.1% scanblock
189 11.4% 23.4% 1549 93.8% main.FindLoops
130 7.9% 31.2% 152 9.2% sweepspan
104 6.3% 37.5% 896 54.2% runtime.mallocgc
98 5.9% 43.5% 100 6.1% flushptrbuf
(pprof)
main.DFS 条目不再出现在性能分析结果中，程序的其余运行时间也有所下降。现在程序大部分时间花在内存分配和垃圾回收上（runtime.mallocgc，负责分配和定期运行垃圾回收，占用了 54.2% 的时间）。要弄清楚为什么垃圾回收器运行得如此频繁，我们必须找出是什么在分配内存。一种方法是向程序添加内存性能分析。我们将安排在提供了 -memprofile 标志时，程序在完成一次循环查找迭代后停止，写入内存性能分析结果，然后退出：
var memprofile = flag.String("memprofile", "", "write memory profile to this file")
...
FindHavlakLoops(cfgraph, lsgraph)
if *memprofile != "" {
f, err := os.Create(*memprofile)
if err != nil {
log.Fatal(err)
}
pprof.WriteHeapProfile(f)
f.Close()
return
}
我们使用 -memprofile 标志调用程序以写入性能分析结果：
$ make havlak3.mprof
go build havlak3.go
./havlak3 -memprofile=havlak3.mprof
$
（参见 与 havlak2 的 diff）
我们使用 go tool pprof 的方式完全相同。现在我们检查的样本是内存分配，而不是时钟周期。
$ go tool pprof havlak3 havlak3.mprof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top5
Total: 82.4 MB
56.3 68.4% 68.4% 56.3 68.4% main.FindLoops
17.6 21.3% 89.7% 17.6 21.3% main.(*CFG).CreateNode
8.0 9.7% 99.4% 25.6 31.0% main.NewBasicBlockEdge
0.5 0.6% 100.0% 0.5 0.6% itab
0.0 0.0% 100.0% 0.5 0.6% fmt.init
(pprof)
命令 go tool pprof 报告称，FindLoops 分配了当前使用中的 82.4 MB 中的大约 56.3 MB；CreateNode 占用了另外 17.6 MB。为了降低开销，内存性能分析器每分配大约半兆字节才记录一个块的信息（“每 524288 个样本中记录 1 个的采样率”），因此这些是实际计数的近似值。
要找到内存分配，我们可以列出这些函数。
(pprof) list FindLoops
Total: 82.4 MB
ROUTINE ====================== main.FindLoops in /home/rsc/g/benchgraffiti/havlak/havlak3.go
56.3 56.3 Total MB (flat / cumulative)
...
1.9 1.9 268: nonBackPreds := make([]map[int]bool, size)
5.8 5.8 269: backPreds := make([][]int, size)
. . 270:
1.9 1.9 271: number := make([]int, size)
1.9 1.9 272: header := make([]int, size, size)
1.9 1.9 273: types := make([]int, size, size)
1.9 1.9 274: last := make([]int, size, size)
1.9 1.9 275: nodes := make([]*UnionFindNode, size, size)
. . 276:
. . 277: for i := 0; i < size; i++ {
9.5 9.5 278: nodes[i] = new(UnionFindNode)
. . 279: }
...
. . 286: for i, bb := range cfgraph.Blocks {
. . 287: number[bb.Name] = unvisited
29.5 29.5 288: nonBackPreds[i] = make(map[int]bool)
. . 289: }
...
看来当前的瓶颈与上一个相同：在可以使用更简单数据结构的地方使用了 map。FindLoops 大约分配了 29.5 MB 的 map。
顺带一提，如果我们使用 --inuse_objects 标志运行 go tool pprof，它将报告分配计数而不是大小：
$ go tool pprof --inuse_objects havlak3 havlak3.mprof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) list FindLoops
Total: 1763108 objects
ROUTINE ====================== main.FindLoops in /home/rsc/g/benchgraffiti/havlak/havlak3.go
720903 720903 Total objects (flat / cumulative)
...
. . 277: for i := 0; i < size; i++ {
311296 311296 278: nodes[i] = new(UnionFindNode)
. . 279: }
. . 280:
. . 281: // Step a:
. . 282: // - initialize all nodes as unvisited.
. . 283: // - depth-first traversal and numbering.
. . 284: // - unreached BB's are marked as dead.
. . 285: //
. . 286: for i, bb := range cfgraph.Blocks {
. . 287: number[bb.Name] = unvisited
409600 409600 288: nonBackPreds[i] = make(map[int]bool)
. . 289: }
...
(pprof)
由于大约 200,000 个 map 占用了 29.5 MB，看起来初始 map 分配大约需要 150 字节。当 map 用于存储键值对时，这是合理的，但当 map 被用作简单集合的替代品时（就像这里），这就不合理了。
除了使用 map，我们可以使用一个简单的切片来列出元素。在使用 map 的所有情况中，除了一个例外，算法都不可能插入重复元素。在剩下的那个例外情况中，我们可以编写一个简单的 append 内建函数变体：
func appendUnique(a []int, x int) []int {
for _, y := range a {
if x == y {
return a
}
}
return append(a, x)
}
除了编写该函数外，将 Go 程序改为使用切片而不是 map 只需修改几行代码。
$ make havlak4
go build havlak4.go
$ ./xtime ./havlak4
# of loops: 76000 (including 1 artificial root node)
11.84u 0.08s 11.94r 810416kB ./havlak4
$
（参见 与 havlak3 的 diff）
现在我们比刚开始时快了 2.11 倍。我们再来看看 CPU 性能分析结果。
$ make havlak4.prof
./havlak4 -cpuprofile=havlak4.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak4 havlak4.prof
Welcome to pprof! For help, type 'help'.
(pprof) top10
Total: 1173 samples
205 17.5% 17.5% 1083 92.3% main.FindLoops
138 11.8% 29.2% 215 18.3% scanblock
88 7.5% 36.7% 96 8.2% sweepspan
76 6.5% 43.2% 597 50.9% runtime.mallocgc
75 6.4% 49.6% 78 6.6% runtime.settype_flush
74 6.3% 55.9% 75 6.4% flushptrbuf
64 5.5% 61.4% 64 5.5% runtime.memmove
63 5.4% 66.8% 524 44.7% runtime.growslice
51 4.3% 71.1% 51 4.3% main.DFS
50 4.3% 75.4% 146 12.4% runtime.MCache_Alloc
(pprof)
现在内存分配及其导致的垃圾回收（runtime.mallocgc）占用了我们运行时间的 50.9%。另一种查看系统频繁进行垃圾回收原因的方法是查看导致回收的分配，即那些在 mallocgc 中花费大部分时间的分配：
(pprof) web mallocgc
很难看清图中发生了什么，因为有很多样本数量很少的节点遮挡了重要的节点。我们可以告诉 go tool pprof 忽略那些样本占比低于 10% 的节点：
$ go tool pprof --nodefraction=0.1 havlak4 havlak4.prof
Welcome to pprof! For help, type 'help'.
(pprof) web mallocgc
现在我们可以轻松地沿着粗箭头看，发现 FindLoops 触发了大部分垃圾回收。如果我们列出 FindLoops 的代码，可以看到大部分分配都在函数开头：
(pprof) list FindLoops
...
. . 270: func FindLoops(cfgraph *CFG, lsgraph *LSG) {
. . 271: if cfgraph.Start == nil {
. . 272: return
. . 273: }
. . 274:
. . 275: size := cfgraph.NumNodes()
. . 276:
. 145 277: nonBackPreds := make([][]int, size)
. 9 278: backPreds := make([][]int, size)
. . 279:
. 1 280: number := make([]int, size)
. 17 281: header := make([]int, size, size)
. . 282: types := make([]int, size, size)
. . 283: last := make([]int, size, size)
. . 284: nodes := make([]*UnionFindNode, size, size)
. . 285:
. . 286: for i := 0; i < size; i++ {
2 79 287: nodes[i] = new(UnionFindNode)
. . 288: }
...
(pprof)
每次调用 FindLoops 时，都会分配一些相当大的簿记结构。由于基准测试调用 FindLoops 50 次，这些分配累积起来产生了大量垃圾，从而给垃圾回收器带来了大量工作。
拥有垃圾回收语言并不意味着您可以忽略内存分配问题。在这种情况下，一个简单的解决方案是引入一个缓存，以便每次调用 FindLoops 时尽可能重用上次调用的存储空间。（事实上，在 Hundt 的论文中，他解释说 Java 程序正是需要这种修改才能获得接近合理的性能，但他在其他具有垃圾回收机制的实现中没有做同样的修改。）
我们将添加一个全局的 cache 结构：
var cache struct {
size int
nonBackPreds [][]int
backPreds [][]int
number []int
header []int
types []int
last []int
nodes []*UnionFindNode
}
然后让 FindLoops 查阅它作为分配的替代方案：
if cache.size < size {
cache.size = size
cache.nonBackPreds = make([][]int, size)
cache.backPreds = make([][]int, size)
cache.number = make([]int, size)
cache.header = make([]int, size)
cache.types = make([]int, size)
cache.last = make([]int, size)
cache.nodes = make([]*UnionFindNode, size)
for i := range cache.nodes {
cache.nodes[i] = new(UnionFindNode)
}
}
nonBackPreds := cache.nonBackPreds[:size]
for i := range nonBackPreds {
nonBackPreds[i] = nonBackPreds[i][:0]
}
backPreds := cache.backPreds[:size]
for i := range nonBackPreds {
backPreds[i] = backPreds[i][:0]
}
number := cache.number[:size]
header := cache.header[:size]
types := cache.types[:size]
last := cache.last[:size]
nodes := cache.nodes[:size]
当然，使用这样的全局变量是不好的工程实践：这意味着现在并发调用 FindLoops 是不安全的。目前，我们正在进行最小可能的修改，以便了解对程序性能来说什么更重要；这个改动很简单，并且反映了 Java 实现中的代码。最终版本的 Go 程序将使用一个独立的 LoopFinder 实例来跟踪这部分内存，从而恢复并发使用的可能性。
$ make havlak5
go build havlak5.go
$ ./xtime ./havlak5
# of loops: 76000 (including 1 artificial root node)
8.03u 0.06s 8.11r 770352kB ./havlak5
$
（参见 与 havlak4 的 diff）
我们可以做更多的工作来清理程序并使其更快，但这都不需要我们尚未展示的性能分析技术。内循环中使用的工作列表可以在迭代和对 FindLoops 的调用之间重用，并且可以与该趟处理中生成的单独的“节点池”结合起来。类似地，循环图存储可以在每次迭代时重用，而不是重新分配。除了这些性能更改外，最终版本使用了符合 Go 语言习惯的风格编写，使用了数据结构和方法。这些风格上的改变对运行时间影响微乎其微：算法和约束条件保持不变。
最终版本在 2.29 秒内运行完成，使用 351 MB 内存：
$ make havlak6
go build havlak6.go
$ ./xtime ./havlak6
# of loops: 76000 (including 1 artificial root node)
2.26u 0.02s 2.29r 360224kB ./havlak6
$
这比我们最初的程序快了 11 倍。即使我们禁用了生成的循环图的重用，使得唯一缓存的内存是循环查找的簿记结构，程序仍然比原始版本快 6.7 倍，并减少了 1.5 倍的内存使用。
$ ./xtime ./havlak6 -reuseloopgraph=false
# of loops: 76000 (including 1 artificial root node)
3.69u 0.06s 3.76r 797120kB ./havlak6 -reuseloopgraph=false
$
当然，将这个 Go 程序与最初的 C++ 程序进行比较已不再公平，后者使用了效率低下的数据结构如 set，而 vector 会更合适。作为一项健全性检查，我们将最终的 Go 程序翻译成了 等效的 C++ 代码。其执行时间与 Go 程序相似：
$ make havlak6cc
g++ -O3 -o havlak6cc havlak6.cc
$ ./xtime ./havlak6cc
# of loops: 76000 (including 1 artificial root node)
1.99u 0.19s 2.19r 387936kB ./havlak6cc
Go 程序的运行速度几乎与 C++ 程序一样快。由于 C++ 程序使用了自动删除和分配而不是显式缓存，C++ 程序稍微短一些，也更容易编写，但差异不大。
$ wc havlak6.cc; wc havlak6.go
401 1220 9040 havlak6.cc
461 1441 9467 havlak6.go
$
（参见 havlak6.cc 和 havlak6.go）
基准测试的效果取决于它们所测量的程序。我们使用 go tool pprof 来研究一个效率低下的 Go 程序，然后将其性能提高了一个数量级，并将其内存使用量减少了 3.7 倍。随后与等效优化的 C++ 程序进行比较表明，当程序员关注内循环产生的垃圾量时，Go 可以与 C++ 竞争。
用于撰写此博文的程序源代码、Linux x86-64 二进制文件和性能分析数据可在 GitHub 上的 benchgraffiti 项目中获取。
如上所述，go test 已包含这些性能分析标志：定义一个 基准测试函数，您就准备好了。还有一个标准的 HTTP 接口用于访问性能分析数据。在一个 HTTP 服务器中，添加：
import _ "net/http/pprof"
将在 /debug/pprof/ 下安装几个 URL 的处理程序。然后您可以运行 go tool pprof 并带一个参数——指向您的服务器性能分析数据的 URL，它将下载并检查实时性能数据。
go tool pprof http://localhost:6060/debug/pprof/profile # 30-second CPU profile
go tool pprof http://localhost:6060/debug/pprof/heap # heap profile
go tool pprof http://localhost:6060/debug/pprof/block # goroutine blocking profile
goroutine 阻塞性能分析将在以后的博文中解释。敬请期待。
下一篇文章：Go 中的头等函数 (First Class Functions)
上一篇文章：聚焦 Go 外部库
博客索引