Go 博客
Go 程序性能分析
在 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++ 的比较应该足够了。）（更新：在此更新后的文章中，我们将使用 Go 编译器在 amd64 上的最新开发快照和 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 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 行），正如从递归遍历中预期的那样。不包括递归，看起来时间花在了第 242、246 和 250 行对 number 映射的访问上。对于特定的查找，映射不是最有效的选择。就像它们在编译器中一样，基本块结构具有分配给它们的唯一序列号。我们可以使用 []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
$
我们可以再次运行性能分析器以确认 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 已经分配了大约 56.3 MB 的内存，占用了 82.4 MB 内存中的大部分；CreateNode 占用了另外 17.6 MB。为了降低开销，内存分析器仅记录大约每 524288 个分配块的信息（“1/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: }
...
看起来当前的瓶颈与上一个相同：在可以使用更简单的数据结构的情况下使用了 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 的差异)。
我们现在比开始时快了 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 的差异)。
我们可以做更多工作来清理程序并使其更快，但其中没有一项需要我们尚未展示的分析技术。内部循环中使用的作业列表可以在迭代之间以及对 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++ 程序进行比较已经不公平了，后者使用了低效的数据结构，例如在 vector 更合适的地方使用 set。作为健全性检查，我们将最终的 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 https://127.0.0.1:6060/debug/pprof/profile # 30-second CPU profile
go tool pprof https://127.0.0.1:6060/debug/pprof/heap # heap profile
go tool pprof https://127.0.0.1:6060/debug/pprof/block # goroutine blocking profile
goroutine 阻塞分析将在以后的文章中解释。敬请期待。