凌云时刻 · 技术

导读：在开发 golang 程序过程中，go pprof 可以对我们所写的算法甚至整个应用程序做性能分析，帮助我们快速定位效率低或者资源消耗多的地方。Go 提供了 pprof 以及 trace 工具，本文分别介绍这两个工具的简要用法，希望大家能够快速了解以及快速入门 Go 的性能调优。

作者 | 谢久阳(昕希)

来源 | 凌云时刻（微信号：linuxpk）

先来一段演练

在给大家介绍枯燥的基础知识之前，先来看看一个简单的例子，这个例子简单粗暴，可以通过 pprof 快速定位协程阻塞问题。

 示例代码

package mainimport (    "fmt"    "net/http"    _ "net/http/pprof"    "time")func main() {    // 是否阻塞的开关    var flag bool    testCh := make(chan int)    go func() {        // pprof 监听的端口 8080        if err := http.ListenAndServe("0.0.0.0:8080", nil); err != nil {            fmt.Printf("%v", err)        }    }()    go func() {        // 永远为 false 的条件        if flag {            <-testCh        }        // 死循环        select {}    }()    // 每秒执行100次    tick := time.Tick(time.Second / 100)    for range tick {        ch1(testCh)    }}func ch1(ch chan<- int) {    go func() {        defer fmt.Println("ch1 stop")        // 给 ch channel 写入数据        ch <- 0    }()}

 编译成二进制

go build -o goroutine-test main.go

 执行并获取 profile 数据

执行测试二进制文件

./goroutine-test

使用 pprof 工具打开第一次，并退出，再次打开，然后退出 pprof， 退出测试程序

go tool pprof xxx/goroutine-test http://localhost:8080/debug/pprof/goroutine

两次结果会默认存储到 $home/pprof 目录中（如果设置了 PPROF_TMPDIR 这个环境变量，则需要到这个环境变量设置的地址中查找 profile 文件）

可以通过 -base 参数来比较一下两次 profile 文件是否有增长，使用如下命令：

go tool pprof -base xxx/goroutine-test xxxx001.pb.gz xxxx002.pb.gz

并使用 top 命令进行简单查看

Entering interactive mode (type "help" for commands, "o" for options)(pprof) topShowing nodes accounting for 640, 99.53% of 643 totalDropped 8 nodes (cum <= 3)      flat  flat%   sum%        cum   cum%       640 99.53% 99.53%        640 99.53%  runtime.gopark         0     0% 99.53%        641 99.69%  main.ch1.func1         0     0% 99.53%        641 99.69%  runtime.chansend         0     0% 99.53%        641 99.69%  runtime.chansend1         0     0% 99.53%        641 99.69%  runtime.goparkunlock(pprof)

从上面内容中，可以看到第二次获取的 profile 文件记录的 goroutine 数量比第一次增加了 640 (flat)个，并且 flat% 占用比例 99.53% ，那基本上就是这里有协程阻塞了

使用 traces 来查看所有 profile 统计信息，包括堆栈的一些内容

(pprof) tracesType: goroutineTime: May 6, 2020 at 9:53am (CST)-----------+-------------------------------------------------------       641   runtime.gopark             runtime.goparkunlock             runtime.chansend             runtime.chansend1             main.ch1.func1-----------+-------------------------------------------------------         1   net/http.(*connReader).backgroundRead-----------+-------------------------------------------------------        -1   runtime.gopark             runtime.netpollblock             internal/poll.runtime_pollWait             internal/poll.(*pollDesc).wait             internal/poll.(*pollDesc).waitRead             internal/poll.(*FD).Read             net.(*netFD).Read             net.(*conn).Read             net/http.(*connReader).backgroundRead-----------+-------------------------------------------------------

在第一行中，看到 641 runtime.gopark ，那么沿着这个调用堆栈来查看，可以看到最下面的调用方法是 main.ch1.func1

使用 list 命令来查看 main.ch1.func1

(pprof) list main.ch1.func1Total: 643ROUTINE ======================== main.ch1.func1 in /Users/xinxi/Desktop/test/main-goroutine.go         0        641 (flat, cum) 99.69% of Total         .          .     32:}         .          .     33:         .          .     34:func ch1(ch chan<- int) {         .          .     35:   go func() {         .          .     36:       defer fmt.Println("ch1 stop")         .        641     37:       ch <- 0         .          .     38:   }()         .          .     39:}

在上面的代码片段，很快的就会定位到 37 行代码给 ch 写入数字 0 的过程中，造成了大量阻塞，目前增加到了 641 个 goroutine 的阻塞

那么就可以去调查为什么 ch 这个 channel 会阻塞？是因为在上面 flag 这个 bool 变量并没有赋值，永远为 false，因此 ch 这个 channel 并没有被读取，因此 37 行代码会一直阻塞，这个程序比较简单，但是实际的产品代码要复杂的多，因此在查找问题的时候并不能一眼就能找到问题，还需要大家多多练习，多多积累。接下来开始介绍比较枯燥的基础知识了，要注意听啦～

pprof 提供了三种方式的使用

 Benchmark

基于基准测试的 pprof，对于已经写好的算法包来说，可以利用基准测试和 pprof 来校验算法是否高效、内存消耗是否合理。

在调用基准测试的时候，传递 -cpuprofile 和 -memprofile 参数，分别来对 cpu 以及内存做 profiling，也可以两个一起用，在这两个参数后面需要加要存储 profiling 文件的路径，如：

# 获取cpu的profiling文件go test -bench=. -benchmem -cpuprofile profile.out# 获取heap的profiling文件go test -bench=. -benchmem -memprofile memprofile.out# 获取cpu以及heap的profiling文件go test -bench=. -benchmem -memprofile memprofile.out -cpuprofile profile.out

生成好的 profiling 文件，可以通过 go tool pprof 命令来直接访问结果数据。后面会以web和控制台来详细介绍如何使用工具。

 单独程序调用

需要引入的包：

import _ "runtime/pprof"

cpu 数据记录：

// file 是 os.File 结构，用来创建 pprof 要写入的文件// 开始写入 cpu 的分析信息pprof.StartCPUProfile(file)// 必须要添加这个，将所有信息在结束前都写入到文件中defer pprof.StopCPUProfile()

heap数据记录：

// file 是 os.File 结构，用来创建 pprof 要写入的文件// 回收之前数据，用来获取最新统计数据runtime.GC()// 开始写入堆数据pprof.WriteHeapProfile(file)

cpu 数据以及 heap 数据多记录到文件中（文件记录在哪，取决于定义的 file），通过 go tool pprof 命令来直接访问结果数据。后面会以web和控制台来详细介绍如何阅读和使用数据。

 web server

如果我们要 profiling 一个服务，比如说 http 或者 grpc 的服务端，那么使用 web server 的方式会更合适。会对外开辟一个 web server，通过指定的端口来访问和下载 pprof 数据

需要引入的包：

_ "net/http/pprof"

需要 main 函数中添加如下内容：

func main() {    go func() {        if err := http.ListenAndServe("0.0.0.0:8080", nil); err != nil {            fmt.Printf("%v", err)        }    }()    ...}

这种方式可以查询以下几种信息：

• profile：展示激活的 goroutine 消耗 cpu 的时间

• heap：会记录内存分配的信息

• threadcreate：记录程序创建系统线程部分内容

• goroutine：记录当前栈中所有 goroutine 的信息

• block: 展示 groutines 在阻塞等待时的信息（敲黑板！这个 block 默认是关闭的，需要使用 runtime.SetBlockProfileRate 来开启）

• mutex：展示锁的争用，当因为互斥锁竞争问题，而不能充分利用 cpu 的时候可以尝试使用（敲黑板！这个 mutex 默认也是关闭的噢，需要使用 runtime.SetMutexProfileFraction 来开启）

• trace：跟踪一段时间内的程序运行，根据生成好的结果来查找程序问题（trace会在最后给大家介绍）

pprof 环境变量以及常用参数

 环境变量

PPROF_TMPDIR：存储pprof文件的位置，默认位置 $HOME/pprof

PPROF_TOOLS：binutils 工具路径，默认在当前目录查找；pprof 工具使用 GNU Binutils 来校验以及反编译二进制；感兴趣的同学可以查阅：https://www.gnu.org/software/binutils/

PPROF_BINARY_PATH：搜索二进制的路径，默认存储在 $HOME/pprof/binaries。如果每找到会按照 $name, $path, $buildid\$name, $path\$buildid 顺序继续查找。

 常用参数

• -base：提供两个 profile 文件，以第一个 profile 为基准，用第二个减去第一个统计的结果（这个参数会更常用一些）

• -diff_base：提供两个 profile 文件比较，显示的百分比是基于第一个 profile 统计的数量

• -http：以 Web UI 的方式打开 pprof 文件

• -seconds：设置指定秒为间隔获取 pprof 信息，这个只在获取时间统计的类型中才生效，如 cpu profiles

• -cum：以累计总量排序

• -flat：以当前统计的数量排序

• -inuse_space：展示使用的空间

• -inuse_objects：展示使用的对象

• -alloc_space：展示总共分配的空间

• -alloc_objects：展示总共分配的对象

pprof 操作

 常用字段含义

• flat：当前函数占用 profile 样本的数量

• flat%：当前函数占用 profile 样本的百分比

• sum%：当前行以上所有 flat% 的和

• cum：累计的 profile 样本量（cum全写：cumulative）

• cum%：累计 profile 样本量占总量的百分比

对于上面的字段，不同的 profile 含义基本相似，比如说 heap profile， flat 就是当前函数内存占用量，如果是 goroutine profile，则是当前函数 goroutine 数量等。

如下面的例子，展示内存占用量：

Showing nodes accounting for 1056.67kB, 100% of 1056.67kB totalShowing top 10 nodes out of 30      flat  flat%   sum%        cum   cum%  544.67kB 34.72% 34.72%   544.67kB 34.72%  google.golang.org/grpc/internal/transport.newBufWriter  512.01kB 32.64%   100%   512.01kB 32.64%  github.com/golang/protobuf/proto.makeMessageMarshaler         0     0%   100%   512.01kB 32.64%  github.com/golang/protobuf/proto.(*InternalMessageInfo).Size         0     0%   100%   512.01kB 32.64%  github.com/golang/protobuf/proto.(*marshalFieldInfo).computeMarshalFieldInfo         0     0%   100%   512.01kB 32.64%  github.com/golang/protobuf/proto.(*marshalFieldInfo).setMarshaler

 控制台

常用命令

• top：默认展示前 10 条样本计数最高的，后面接数字，则显示指定数字的条目，如：top3

• traces：输出所有 profile 的统计信息

• list：输出给定正则表达式匹配的方法源码，list 后面是可以接正则表达式

• tree：输出所有调用关系

• web：生成 profile 的 svg 矢量图片并用 web 打开，如果不指定参数则显示所有，给定指定方法，则显示指定的方法

• pdf：生成 pdf 的 profile 文件，里面展示 profile 图片的内容

• cum：按照累计的 profile 样本量排序

• flat：按照当前函数占用的 profile 排序

正如我们最刚开始的示例一样，top、traces 和 list 是最常用的三个命令，通过 top 来快速查看那里占用最高，然后通过 traces 来快速定位，最后通过 list 来查看哪里代码的问题

 Web

在使用 pprof 命令的时候指定 -http 参数即可，如：

go tool pprof -http=:8080 [profiling file path]

 图形部分内容含义

• Flat 值：当前函数 profile 的值，在图表中以字体大小来展示，字体大，代表 flat 值大；字体小，代表 flat 值小

• Cum 值：累计的 profile 值（包含子节点），在图表中以节点的颜色来展示，红色代表当前值比较大，灰色代表值比较小，绿色代表值为负的

• 实体线：当前节点调用另外一个节点，箭头指向谁，则代表当前节点调用谁

• 粗的红色实体线：在这个路径上使用了更多的资源

• 细的实体线：在这个路径上使用了相对较少的资源

• 虚线：代表省略了当中的过程，pprof 会根据情形来省略其中一些内部调用关系，让整套图展示更容易

在 web ui 中也可以查看 top 的信息内容，另外可以使用 http://host:port/ui/flamegraph 来展示火焰图等信息

看了这么多基础的环境变量、参数以及命令，那么再回过去回味一下刚开始的示例，结合命令行以及web图形再操作一遍，就会更轻松的理解，另外需要根据自己碰到不同情况来使用不同的命令和参数。

Trace

Trace 也是 go 工具链中比较重要的工具，它与上面 pprof 的本质区别为：

• pprof 更擅长去查看程序效率，比如说你要查看谁占用内存时间长，谁的协程阻塞了等等

• trace 则是程序在运行期间的信息追踪，通过可视化的方式来查看这期间程序到底做了什么，以及了解 GC 对程序的影响等等

但这两套工具配合起来，就会让我们更快速的发现问题，以及解决问题

那对于trace来说也是分成了三种：web、单元测试和应用程序，web 调用方式相同，单元测试是添加 -trace 参数，应用程序的话需要添加如下代码：

// 需要引入的包import _ "runtime/pprof"// file 是 os.File 结构，用来创建 pprof 要写入的文件// 开始 tracetrace.Start(file)// 结束 trace，并将trace信息完全写入到文件中defer trace.Stop()

执行完毕后，会生成 trace 的文件。

对于 web 来说，通过下面命令来下载指定时段的 trace 文件：

curl "http://localhost:8080/debug/pprof/trace?seconds=50" > trace.log

其中 ?seconds=50 是指获取50秒的 trace 信息，可根据具体情况来设置这个时间

 查看 trace 信息

通过如下命令来打开 trace：

go tool trace [trace file path]

执行完上面的命令后，会自动打开浏览器，并且在默认页面上会显示几个超链接

• View trace：以图形界面的形式展示 trace 的内容

• Goroutine analysis：协程分析，会列出协程数量以及各个协程调用时间

• Network blocking profile：用调用关系图展示网络阻塞的情况

• Synchronization blocking profile：同步阻塞耗时情况，使用调用关系图来展示

• Syscall blocking profile：系统调用阻塞耗时情况，使用调用关系图来展示

• Scheduler latency profile：调度器延迟耗时情况，使用调用关系图来展示

• User-defined tasks：用户自定义 trace 的 tasks

• User-defined regions：用户自定义 trace 的 region

• Minimum mutator utilization：不太好翻译成中文（保持原有名词，大家自己体会），这个会用一个曲线图来展示 GC 对我们程序影响的情况，它可以用来分析和判断是否要对 GC 做优化

User-defined tasks 和 User-defined regions 这两个大家可能不清楚是做什么的，甚至点开也是没有什么有用的东西；其实这个是在 go 1.11 版本中引入的特性，trace 可以添加我们自定义的内容，用来快速跟踪我们想要看到的代码块的耗时点，因此 trace 提供了三个概念，分别是：message ，task，region ，其中 region 是可以含有 task 的，针对 message ，task 和 region 我之后单独再给大家写一篇文章来描述如何使用吧。

对于上面这么多 trace 内容，我们本篇文章主要关注 View trace 和 Minimum mutator utilization 。

 View trace

点开 View trace 后，会显示下面的图形

通过 trace 图形，可以快速看到程序整体运行耗时的时间，以及 GC 等信息，也可以看到所有执行中的协程。

在这个界面中，可以通过快捷键来操作：

• w 按键：放大图形，主要是以鼠标所在的位置来放大

• s 按键：缩小图形，主要是以鼠标所在的位置来缩小

• a 按键：图形往右移动

• d 按键：图形往左移动

界面中方的图形是矢量的，我们可以放大来查看具体的协程执行情况，以及 GC 的 mark assist 和 STW（Stop the world）情况

上面图太复杂了，我们找一个协程数量少的图形来给大家看一下

在这个图中，我们有6个协程，在每个协程上都有其编号，他们的含义如下：

• G1：main 函数

• G18：trace 的协程

• G19，G20，G21，G22 是 main 函数中开启的四个协程

第一个 G1 到最后那个 G1 结束，就是程序运行的时间；从图中可以快速发现 G19 到 G22 协程中间都有一块空白，这空白就是协程暂停了（可能是在等待什么，导致阻塞了），四个协程都暂停了一小段时间才继续执行的，会导致效率变低，可能无法达到我们的预期。

对于这个暂停，是我添加了一个互斥锁，这个锁要等一小段时间才会解锁，所以每个协程在获取 task 的时候都需要等待锁解锁才能继续执行，因此造成了性能不符合预期的情况。那么对于这个锁，我们可以根据自己的需要来做各种方式的优化，以达成最优效果。

 Minimum mutator utilization

这个工具是在 go 1.12 这个版本中引入进来的，他的主要作用是辅助查看 GC 对我们程序的影响，默认的图形如下：

从这个曲线图中，可以看到，大约80微秒后我们的程序才获得到 cpu 使用，那在这 80 微秒之前，GC 做了 STW （stop the world），随着横坐标的时间增加，曲线开始逐渐趋近 100%，意味着我们的程序对 cpu 可用率越来越高，从这个曲线上来看，GC 还可以，并不需要做什么优化，如果曲线随着时间增加依然不高，说明 GC 负担比较重，占用了更多系统资源，这个时候我们需要对 GC 做优化了。

曲线图右侧有几个选项，他们的含义是：

• System：整个系统的利用率

• Per-goroutine：每一个协程的利用率

• STW：Stop the word，表示所有协程同时暂停，在做 GC 的时，是会 STW

• Backgroud workers：GC 的协程，会消耗 25% 的利用率，在 GC 的时候，会以后台方式执行

• Mark assisst：GC 要减慢内存分配速度时，会分配 goroutine 来做标记

• Sweep：回收在 GC 之间未使用的内存

• Show percentiles：除了最基本数据外，还显示 mutator 利用率的百分比

每选择一个选项，曲线都会有相应的变化，大家可根据各自需求来查看。

总结

对于开发人员来说，单元测试，code review 甚至集成测试都是非常重要的，但这些方法未必能够发现和定位隐性问题，如：goroutine 阻塞，内存消耗过多，cpu 利用率超高等等，这些问题在前期是很难发现的，但如果不能在上线前发现和解决，则会容易碰到一些始料未及的故障，会非常被动，所以花一些时间对程序做一轮性能分析和调优，也许会有意想不到的效果。

END

往期精彩文章回顾

长按扫描二维码关注凌云时刻

每日收获前沿技术与科技洞见