解读pprof报告

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

先了解是如何采样的:

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

解读图

解读源码

下面是在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)

下面是在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

解读内存

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

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

解读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)

采样频率:

照例我们加上列:

解读源码

和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%的结果:

可以看到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

参考资料