凌云时刻 · 技术

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

作者 | 谢久阳(昕希)

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

先来一段演练

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

 示例代码

package main


import (
    "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/pprofPPROF_TMPDIR
-base
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) top
Showing nodes accounting for 640, 99.53% of 643 total
Dropped 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) traces
Type: goroutine
Time: 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.goparkmain.ch1.func1
main.ch1.func1
(pprof) list main.ch1.func1
Total: 643
ROUTINE ======================== 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

pprof 提供了三种方式的使用

 Benchmark

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

-cpuprofile-memprofile
# 获取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

go tool pprof

 单独程序调用

需要引入的包：

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)

go tool pprof

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


    ...
}

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

runtime.SetBlockProfileRateruntime.SetMutexProfileFraction

pprof 环境变量以及常用参数

 环境变量

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

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

$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 total
Showing 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 会根据情形来省略其中一些内部调用关系，让整套图展示更容易

http://host:port/ui/flamegraph

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

Trace

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

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

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

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

-trace
// 需要引入的包
import _ "runtime/pprof"


// file 是 os.File 结构，用来创建 pprof 要写入的文件
// 开始 trace
trace.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 tasksUser-defined regionsmessagetaskregionregiontaskmessagetaskregion
View traceMinimum mutator utilization

 View trace

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

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

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

wsad

界面中方的图形是矢量的，我们可以放大来查看具体的协程执行情况，以及 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

往期精彩文章回顾

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

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