译 | Profiling Go Programs（一）

背景

在Scala Days 2011，Robert Hundt 发表了一篇名为 Loop Recognition in C++/Java/Go/Scala 的论文。 该论文实现了一种特定的循环查找算法，例如您可以在C++，Go，Java，Scala编译器的流分析传递中使用，然后使用这些程序得到这些语言中典型性能问题的结论。该论文中的Go程序运行速度非常慢，使它成为演示的绝佳机会：如何使用Go的分析工具来实现慢速程序并使其更快。

通过使用go的分析工具来识别和纠正特定的瓶颈，可以使go loop finding程序运行速度提高一个数量级，并减少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’s 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’s benchmark programs 的C++和Go部分，将每个程序组合成一个单独的源文件，并删掉了除一行输出之外的所有内容。我们将使用Linux的time工具为程序计时 ，其格式显示为 user time, system time, real time, and maximum memory usage:

Mac OS 需要 brew install gnu-time，使用 gtime 命令替代

$ 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，而不是重现论文的结果。）

CPU Profile

要调优Go程序，我们必须启用profiling。 如果代码使用Go testing package的benchmarking分析，可以使用gotest标准的 -cpuprofile 和 -memprofile flags 。 我们必须在程序中导入 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 的flag，调用 Go flag library 来解析命令行flags，如果在命令行上设置了 cpuprofile flag，则 starts CPU profiling 重定向到该文件。 在程序退出之前，profiler 需要最后调用 StopCPUProfile 来flush未写入文件的数据; 我们使用 defer 来确保在 main 返回前执行该调用。

添加该代码后，我们可以使用新的 -cpuprofile flag 运行程序，然后运行 go tool pprof 来解释 profile。

$ 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’s pprof C++ profiler 的细微变体。最重要的命令是 topN ，显示profile中 top 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 profiling 启用时，Go程序每秒大约停止100次，并在当前正在执行的goroutine堆栈上记录由程序计数器组成的样本。 该 profile 有2525个样本，因此运行时间超过25秒。 在 go tool pprof 输出中，样本中出现的每个函数都有一行。

• 前两列显示函数运行的样本数（而不是等待被调用函数返回），展示为原始计数和总样本的百分比。 runtime.mapaccess1_fast64 函数在298个样本期间运行(11.8％)。 top10 输出按样本计数排序。
• 第三列显示了清单期间的运行总数：前三行占样本的32.4％。
• 第四和第五列显示函数出现的样本数（运行或等待被调用的函数返回）。 main.FindLoops函数在10.6％的样本中运行，但是它在84.1％的样本中位于调用堆栈（它或它的调用正在运行）上。

要按第四和第五列排序，要使用 -cum（for cumulative）flag：

(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多帧，因此完整的trace被截断。

stack trace样本包含有关函数调用关系，不是文本列表可以显示的有趣数据。 web 命令以SVG格式输出profile数据为图像，并在Web浏览器中打开它。 （还有一个 gv 命令可以编写PostScript并在Ghostview中打开它。两个命令都需要安装 graphviz 。）

(pprof) web

完整图形的一小部分如下：

图中的每个框对应于一个函数，并且框根据函数运行的样本数来确定大小。 从方框X到方框Y的线表示X调用Y; 沿线的数字是调用在样本中出现的次数。 如果在单个样本中多次出现呼叫，例如在递归函数调用期间，则每次出现都会计入线权重。 解释了从 main.DFS 到自身的线的上的权重：21342。