Go程序性能分析
Russ Cox，2011年7月；Shenghou Ma更新，2013年5月
2011年6月24日
在2011年的Scala Days上，Robert Hundt发表了一篇题为《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编译器的最新开发快照和2013年3月发布的最新版本的g++ – 4.8.0。）
$ 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 RAM运行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测试包的基准支持，我们可以使用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标志库解析命令行标志，然后如果在命令行上设置了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格式写入图表并在Web浏览器中打开。（还有一个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命令混合了两种模式：它显示一个源列表，点击行可以显示反汇编。
由于我们已经知道时间花在哈希查找由运行时函数实现的查找上，我们最关心的是第二列。大量时间花在递归调用DFS（第247行）上，这在递归遍历中是预期的。排除递归，看起来时间花在了number映射的访问上（第242、246和250行）。对于特定查找，映射不是最有效的选择。正如在编译器中一样，基本块结构具有唯一的顺序号分配给它们。我们可以使用一个[]int，而不是使用map[*BasicBlock]int，这是一个按块号索引的切片。当数组或切片可以使用时，没有理由使用映射。
将number从映射更改为切片需要编辑程序中的七行并将运行时间减少了近一半：
$ 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之间的差异）
我们可以再次运行分析器以确认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的差异）
我们以相同的方式使用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。为了减少开销，内存分析器仅记录每分配约半兆字节的一个块的信息（“1-in-524288采样率”），因此这些是实际计数的近似值。
要找到内存分配，可以列出那些函数。
(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: }
...看起来当前的瓶颈与上一个相同：使用映射而简单数据结构更合适。FindLoops分配了大约29.5 MB的映射。
顺便说一句，如果我们运行go tool pprof带--inuse_objects标志，它将报告分配计数而不是大小：$ 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个映射占用29.5 MB，看来初始映射分配占用了大约150字节。当映射用于存储键值对时，这是合理的，但当映射用作简单集合的替代时，这就不合适了。
我们可以使用一个简单的切片来列出元素，而不是使用映射。在除一个情况下，算法无法插入重复元素。在剩下的一个情况下，我们可以编写append内置函数的简单变体：func appendUnique(a []int, x int) []int {
for _, y := range a {
if x == y {
return a
}
}
return append(a, x)
}除了编写该函数，改变Go程序以使用切片而不是映射需要改变几行代码。$ 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的差异）
现在速度比我们开始时快了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程序需要进行这种更改才能获得合理的性能，但他没有在其他垃圾收集实现中进行同样的更改。）
我们将添加一个全局缓存结构：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的差异）
我们还有更多的事情可以做来清理程序并使其更快，但没有任何需要我们尚未展示的分析技术。内循环中使用的工作列表可以在迭代之间和对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++程序进行比较已不再公平，后者使用了不太合适的数据结构如集合，而向量更为合适。作为理智检查，我们将最终的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 ./havlak6ccGo程序运行几乎和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阻塞分析将在后续文章中解释。敬请期待。