GO语言-解读pprof内信息

发布于 2021-09-14  827 次阅读


简介

pprof是性能调试工具,可以生成类似火焰图、堆栈图,内存分析图等。

整个分析的过程分为两步:1. 导出数据,2. 分析数据。

使用

一、查看实时数据

import包

import (
	"net/http"
	_ "net/http/pprof"
)

在代码开始的地方添加,一般是在main的执行函数开始的地方

go func() {
   log.Println(http.ListenAndServe(":6060", nil))
}()

然后打开浏览器输入:http://127.0.0.1:6060/debug/pprof/,即可查看实时的信息

  • allocs:查看过去所有内存分配的样本。
  • block:查看导致阻塞同步的堆栈跟踪。
  • cmdline: 当前程序的命令行的完整调用路径。
  • goroutine:查看当前所有运行的 goroutines 堆栈跟踪。
  • heap:查看活动对象的内存分配情况。
  • mutex:查看导致互斥锁的竞争持有者的堆栈跟踪。
  • profile: 默认进行 30s 的 CPU Profiling,得到一个分析用的 profile 文件。
  • threadcreate:查看创建新 OS 线程的堆栈跟踪。
  • trace:略,trace可以单独写一篇文章来介绍。

注意,默认情况下是不追踪block和mutex的信息的,如果想要看这两个信息,需要在代码中加上两行:

    runtime.SetBlockProfileRate(1) // 开启对阻塞操作的跟踪,block  
    runtime.SetMutexProfileFraction(1) // 开启对锁调用的跟踪,mutex

二、导出数据

有两种方式下载

直接运行go tool pprof http://localhost:6060/debug/pprof/XXX,其会自动下载数据到本地,然后供你分析。(这个命令具体怎么用,见后文)

方法二:

访问http://localhost:6060/debug/pprof/XXX,游览器就会提醒你下载文件。

这里有一个小点要注意,在这个页面下,点击profiletrace总是会下载文件。而点击其他链接会跳转到另一个页面,来展示一些数据,但是可读性也比较差。

如果点击profile,程序会开始进行半分钟(默认值)的CPU采样,然后才会下载文件。

在跳转到页面中,会发现URL带有?debug=1的后缀,如果把这个后缀去掉,则也会提示你下载文件。

总之,目前这个页面最有用的数据就是直接看看协程数,看看同步数,看看堆和线程创建数。点进去的链接基本都没太强的可读性。操作到这里,能看到这个网页即可。

注:这里采用的是 将数据导出成文件:

分析数据

地址:https://chanjarster.github.io/post/go/pprof-explained/

文件导出的后在go环境下运行命令:

1. go tool pprof pprof.gos-game.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb
2. go tool pprof http://url地址

或者通过页面来分析

go tool pprof -http=:8000 pprof/pprof.gos-game.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb

解读数据

解读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
  • 方框:函数
  • 方框尺寸:代表了Flat的次数
  • 箭头:X调用Y
  • 线条:记录了X调用Y的次数。数字越大,线条越粗。图中main.DFS有一个指向自己的箭头,说明存在递归调用,而且调用了21342次()。
  • 方框第一行数字:Flat (Flat%),栈顶次数
  • 方框第二行数字:Cum (Cum%),调用次数

解读源码

(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

解读内存

以文中提供的内存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的数量
(pprof) top5
Showing nodes accounting for 855.54MB, 46.66% of 1833.72MB total
Dropped 950 nodes (cum <= 9.17MB)
Showing top 5 nodes out of 164
      flat  flat%   sum%        cum   cum%
  463.33MB 25.27% 25.27%   463.33MB 25.27%  su/goslib/core/persist.(*MsgCache).Add
  117.76MB  6.42% 31.69%   403.70MB 22.02%  su/game/confs/gen/pt.(*PlayerData).Unmarshal
   96.16MB  5.24% 36.93%    96.16MB  5.24%  su/game/app/models/data/user_data.SetExploreSite
   91.09MB  4.97% 41.90%    93.59MB  5.10%  su/game/app/task_observer.UpdateSub
   87.20MB  4.76% 46.66%    87.20MB  4.76%  su/game/confs/gen/pt.(*FreeBuildInfo).Unmarshal

采样频率:

  • 每分配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:     }
...