解读 Golang pprof 报告

Go开发大全

【导读】在读 go 的 pprof 报告时候如何理解里面的数字？本文在官方文档基础上进一步解释了这些指标的含义。

Profiling Go Programs(https://blog.golang.org/profiling-go-programs) 里详细举例说明了如何看 pprof 报告，但并没有清晰简明的告知读者提供数字的是什么意思，所以本文做一个归纳笔记。

解读 CPU

以文中提供的 CPU Profile 来举例说明，我们使用go tool pprof -http=0.0.0.0:4231 havlak1 havalk1.prof来观察

解读 Top

(pprof) top10
Total: 2525 samples
    Flat  Flat%   Sum%      Cum   Cum% Name
     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

先了解是如何采样的：

采样频率是每秒 100 次
一个样本包含 goroutine 栈的程序计数器（program counters）
每次只会采样调用栈的前 100 行

原文中没有给出列名，这里给了出来，下面是解释：

Total：总共采样次数，这里是 2525 次。
Flat：函数在样本中处于运行状态的次数。简单来说就是函数出现在栈顶的次数，而函数在栈顶则意味着它在使用 CPU。
Flat%：Flat / Total。
Sum%：自己以及所有前面的 Flat%的累积值。解读方式：表中第 3 行 Sum% 32.4%，意思是前 3 个函数（运行状态）的计数占了总样本数的 32.4%
Cum：函数在样本中出现的次数。只要这个函数出现在栈中那么就算进去，这个和 Flat 不同（必须是栈顶才能算进去）。也可以解读为这个函数的调用次数。
Cum%：Cum / Total

解读图

1img

方框：函数
方框尺寸：代表了 Flat 的次数
箭头：X 调用 Y
线条：记录了 X 调用 Y 的次数。数字越大，线条越粗。图中 main.DFS 有一个指向自己的箭头，说明存在递归调用，而且调用了 21342 次。
方框第一行数字：Flat (Flat%)，栈顶次数
方框第二行数字：Cum (Cum%)，调用次数

解读源码

下面是在 pprof 交互 cli 界面看到的报告：

(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)

第一列：Flat
第二列：Cum
第三列：行号

下面是在 Web 界面看到的报告（基本差不多，见这里）：

havlak1
Total: 5758 samples
main.DFS
/home/rsc/g/benchgraffiti/havlak/havlak1.go

Total:   225   2296 (flat / cumulative samples)
  235                return false
  236               }
  237               
  238               // DFS - Depth-First-Search and node numbering.
  239               //
  240      3      3 func DFS(currentNode *BasicBlock, nodes []*UnionFindNode, number map[*BasicBlock]int, last []int, current int) int {
  241     18     19  nodes[current].Init(currentNode, current)
  242           166  number[currentNode] = current
  243               
  244      2      2  lastid := current
  245    167    167  for _, target := range currentNode.OutEdges {
  246     17    508   if number[target] == unvisited {
  247     10   1157    lastid = DFS(target, nodes, number, last, lastid+1)
  248                 }
  249                }
  250      7    273  last[number[currentNode]] = lastid
  251      1      1  return lastid
  252               }
  253               
  254               // FindLoops
  255               //
  256               // Find loops and build loop forest using Havlak's algorithm, which

第一列：行号
第二列：Flat
第三列：Cum

解读内存

以文中提供的内存 Profile 来举例说明，我们使用go tool pprof -http=0.0.0.0:4231 havlak3 havalk3.mprof来观察。

pprof 提供了 4 种视角，默认是-inuse_space：

-inuse_space ：live object 占用内存
-inuse_objects ：live object 的数量
-alloc_space ：程序启动到现在，总共分配的内存
-alloc_objects ：程序启动到现在总共 object 的数量

解读 Top

(pprof) top5
Total: 82.4 MB
    Flat  Flat%   Sum%      Cum   Cum% Name
    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)

采样频率：

每分配 512K，采样一个 block（具体啥意思不知道）

照例我们加上列：

Total：总共占用内存
Flat：函数分配的内存，不包含它调用其他函数造成的内存分配。
Flat%：Flat / Total
Sum%：自己和前面所有的 Flat%累积值
Cum：这个函数分配的内存，以及它调用其他函数分配的内存之和。可以解读为因为这个函数所造成的所有内存分配。
Cum%：Cum / Total

解读源码

和 CPU 源码解读差不多：

(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:     }
...

可以发现 L288 占用了 29.5M 内存。用-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)

分析 GC

你可以通过 CPU Profile 来分析 GC：

(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 中花费了大部分时间。使用--nodefraction=0.1去掉占比小于 10%的结果：

img

可以看到main.FindLoops导致了大多数 GC。

在线 Profile

如果你是一个 Web 应用，你可以使用 net/http/pprof 来添加一个 Handler，访问http://<host>:<port>/debug/pprof/可以得到功能列表：

/debug/pprof/

Types of profiles available:
Count Profile
8   allocs
0   block
0   cmdline
10 goroutine
8   heap
0   mutex
0   profile
19 threadcreate
0   trace
...

然后你可以通过这样来用go tool pprof <url>来分析，比如：

# 分析 CPU
go tool pprof http://localhost:9090/debug/pprof/profile
# 打开网页分析 heap
go tool pprof -http=0.0.0.0:4231 http://localhost:9090/debug/pprof/heap

在生产中，你需要对/debug/pprof/*做 HTTP BasicAuth 保护（很简单，一个响应头和请求头罢了），那么你去抓取数据分析的时候得这样：

go tool pprof http://<user>:<password>@localhost:9090/debug/pprof/profile

转自：
chanjarster.github.io/post/go/pprof-explained/

- EOF -