我们可以一目了然看到该程序将大部分时间花在哈希操作上，这与使用Go的 map 值相对应。 我们让 web 只使用包含特定函数的样本，例如 runtime.mapaccess1_fast64 ，可以清除图中的一些噪音：
(pprof) web mapaccess1
如果斜视，我们可以看到 main.FindLoops 和 main.DFS 对 runtime.mapaccess1_fast64 的调用。
现在我们已经大致了解了大局，现在是时候放大一个特定的函数了。 让我们先看看 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 map的访问。对于特定查找，map 不是最有效的选择。 正如它们在编译器中一样，basic block 结构具有分配给它们的唯一序列号。 我们可以使用 []int 替代 map[*BasicBlock]int，这是一个由block number索引的slice。 当数组或slice可以使用时，没有理由使用map。
将 number 从map更改为slice需要在程序中编辑七行，并将其运行时间减少近1/2：
$ make havlak2 go build havlak2.go $ ./xtime ./havlak2 # of loops: 76000 (including 1 artificial root node) 16.55u 0.11s 16.69r 1321008kB ./havlak2 $
GC Memory Profile
我们可以再次运行 profiler 来确认 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 不再出现在 profile 中，程序 runtime 的其余部分也已消失。 现在该程序花费大部分时间来分配内存和垃圾收集（ runtime.mallocgc，分配和运行定期垃圾收集，占54.2％的时间）。 为了找出垃圾收集器运行如此多的原因，我们必须找出分配内存的原因。 一种方法是向程序添加 memory profiling。 我们改写程序，如果提供 -memprofile flag，程序在循环查找一次迭代后停止，写入 memory profile，并退出：
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 flag 调用程序写入 profile：
$ make havlak3.mprof go build havlak3.go ./havlak3 -memprofile=havlak3.mprof $
我们以完全相同的方式使用 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个82.4 MB; CreateNode 占另外的17.6 MB。 为了减少开销，内存分析器分配每半兆字节大约只记录一个块的信息。（“1-in-524288采样率”），因此这些是实际计数的近似值。
