Go语言精进之路：从新手到高手的编程思想、方法和技巧 2最新章节_白明著

47.1　pprof的工作原理

使用pprof对程序进行性能剖析的工作一般分为两个阶段： 数据采集 和 数据剖析 ，如图47-1所示。

图47-1　pprof工作原理

1．采样数据类型

在 数据采集阶段 ，Go运行时会定期对剖析阶段所需的不同类型数据进行采样记录。当前主要支持的采样数据类型有如下几种。

（1）CPU数据（对应图47-1中的cpu.prof）

CPU类型采样数据是性能剖析中十分常见的采样数据类型，它能帮助我们识别出代码关键路径上消耗CPU最多的函数。一旦启用CPU数据采样，Go运行时会每隔一段短暂的时间（10ms）就中断一次（由SIGPROF信号引发）并记录当前所有goroutine的函数栈信息（存入cpu.prof）。

（2）堆内存分配数据（对应图47-1中的mem.prof）

堆内存分配采样数据和CPU采样数据一样，也是性能剖析中十分常见的采样数据类型，它能帮助我们了解Go程序的当前和历史内存使用情况。堆内存分配的采样频率可配置，默认每1000次堆内存分配会做一次采样（存入mem.prof）。

（3）锁竞争数据（对应图47-1中的mutex.prof）

锁竞争采样数据记录了当前Go程序中互斥锁争用导致延迟的操作。如果你认为很大可能是互斥锁争用导致CPU利用率不高，那么你可以为go tool pprof工具提供此类采样文件以供性能剖析阶段使用。该类型采样数据在默认情况下是不启用的，请参见runtime.SetMutexProfileFraction或go test -bench . xxx_test.go -mutexprofile mutex.out启用它。

（4）阻塞时间数据（对应图47-1中的block.prof）

该类型采样数据记录的是goroutine在某共享资源（一般是由同步原语保护）上的阻塞时间，包括从无缓冲channel收发数据、阻塞在一个已经被其他goroutine锁住的互斥锁、向一个满了的channel发送数据或从一个空的channel接收数据等。该类型采样数据在默认情况下也是不启用的，请参见runtime.SetBlockProfileRate或go test -bench . xxx_test.go -blockprofile block.out启用它。

注意，采样不是免费的，因此 一次采样尽量仅采集一种类型的数据 ，不要同时采样多种类型的数据，避免相互干扰采样结果。

2．性能数据采集的方式

在图47-1中我们看到，Go目前主要支持两种性能数据采集方式：通过性能基准测试进行数据采集和独立程序的性能数据采集。

（1）通过性能基准测试进行数据采集

为应用中的关键函数/方法建立起性能基准测试之后，我们便可以通过执行性能基准测试采集到整个测试执行过程中有关被测方法的各类性能数据。这种方式尤其适用于对应用中关键路径上关键函数/方法性能的剖析。

我们仅需为go test增加一些命令行选项即可在执行性能基准测试的同时进行性能数据采集。以 CPU采样数据类型 为例：

$go test -bench . xxx_test.go -cpuprofile=cpu.prof
$ls
cpu.prof xxx.test* xxx_test.go

一旦开启性能数据采集（比如传入 -cpuprofile ），go test的-c命令选项便会自动开启，go test命令执行后会自动编译出一个与该测试对应的可执行文件（这里是xxx.test）。该可执行文件可以在性能数据剖析过程中提供剖析所需的符号信息（如果没有该可执行文件，go tool pprof的disasm命令将无法给出对应符号的汇编代码）。而cpu.prof就是存储CPU性能采样数据的结果文件，后续将 作为数据剖析过程的输入 。

对于其他类型的采样数据，也可以采用同样的方法开启采集并设置输出文件：

$go test -bench . xxx_test.go -memprofile=mem.prof
$go test -bench . xxx_test.go -blockprofile=block.prof
$go test -bench . xxx_test.go -mutexprofile=mutex.prof

（2）独立程序的性能数据采集

可以通过标准库runtime/pprof和runtime包提供的低级API对独立程序进行性能数据采集。下面是一个独立程序性能数据采集的例子：

// chapter8/sources/pprof_standalone1.go

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
var memprofile = flag.String("memprofile", "", "write memory profile to `file`")
var mutexprofile = flag.String("mutexprofile", "", "write mutex profile to `file`")
var blockprofile = flag.String("blockprofile", "", "write block profile to `file`")

func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal("could not create CPU profile: ", err)
        }
        defer f.Close() // 该例子中暂忽略错误处理
        if err := pprof.StartCPUProfile(f); err != nil {
            log.Fatal("could not start CPU profile: ", err)
        }
        defer pprof.StopCPUProfile()
    }

    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal("could not create memory profile: ", err)
        }
        defer f.Close()
        if err := pprof.WriteHeapProfile(f); err != nil {
            log.Fatal("could not write memory profile: ", err)
        }
    }

    if *mutexprofile != "" {
        runtime.SetMutexProfileFraction(1)
        defer runtime.SetMutexProfileFraction(0)
        f, err := os.Create(*mutexprofile)
        if err != nil {
            log.Fatal("could not create mutex profile: ", err)
        }
        defer f.Close()

        if mp := pprof.Lookup("mutex"); mp != nil {
            mp.WriteTo(f, 0)
        }
    }

    if *blockprofile != "" {
        runtime.SetBlockProfileRate(1)
        defer runtime.SetBlockProfileRate(0)
        f, err := os.Create(*blockprofile)
        if err != nil {
            log.Fatal("could not create block profile: ", err)
        }
        defer f.Close()

        if mp := pprof.Lookup("mutex"); mp != nil {
            mp.WriteTo(f, 0)
        }
    }

    var wg sync.WaitGroup
    c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
    wg.Add(1)
    go func() {
        for {
            select {
            case <-c:
                wg.Done()
                return
            default:
                s1 := "hello,"
                s2 := "gopher"
                s3 := "!"
                _ = s1 + s2 + s3
            }

            time.Sleep(10 * time.Millisecond)
        }
    }()
    wg.Wait()
    fmt.Println("program exit")
}

可以通过指定命令行参数的方式选择要采集的性能数据类型：

$go run pprof_standalone1.go -help
Usage of /var/folders/cz/sbj5kg2d3m3c6j650z0qfm800000gn/T/go-build221652171/b001/exe/pprof_standalone1:
  -blockprofile file
        write block profile to file
  -cpuprofile file
        write cpu profile to file
  -memprofile file
        write memory profile to file
  -mutexprofile file
        write mutex profile to file

以CPU类型性能数据为例，执行下面的命令：

$go run pprof_standalone1.go -cpuprofile cpu.prof
^Cprogram exit


$ls -l cpu.prof
-rw-r--r--  1 tonybai  staff  734  5 19 13:02 cpu.prof

程序退出后，我们在当前目录下看到采集后的CPU类型性能数据结果文件cpu.prof，该文件将被提供给go tool pprof工具用作后续剖析。

从上述示例我们看到，这种独立程序的性能数据采集方式对业务代码侵入较多，还要自己编写一些采集逻辑：定义flag变量、创建输出文件、关闭输出文件等。每次采集都要停止程序才能获取结果。（当然可以重新定义更复杂的控制采集时间窗口的逻辑，实现不停止程序也能获取采集数据结果。）

Go在net/http/pprof包中还提供了一种更为高级的针对独立程序的性能数据采集方式，这种方式尤其适合那些内置了HTTP服务的独立程序。net/http/pprof包可以直接利用已有的HTTP服务对外提供用于性能数据采集的服务端点（endpoint）。例如，一个已有的提供HTTP服务的独立程序代码如下：

// chapter8/sources/pprof_standalone2.go

func main() {
    http.Handle("/hello", http.HandlerFunc(func(w http.ResponseWriter,
        r *http.Request) {
        fmt.Println(*r)
        w.Write([]byte("hello"))
    }))
    s := http.Server{
        Addr: "localhost:8080",
    }
    c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
    go func() {
        <-c
        s.Shutdown(context.Background())
    }()
    log.Println(s.ListenAndServe())
}

如果要采集该HTTP服务的性能数据，我们仅需在该独立程序的代码中像下面这样导入net/http/pprof包即可：

// chapter8/sources/pprof_standalone2.go

import (
    _ "net/http/pprof"
)

下面是net/http/pprof包的init函数，这就是空导入net/http/pprof的“副作用”：

//$GOROOT/src/net/http/pprof/pprof.go

func init() {
    http.HandleFunc("/debug/pprof/", Index)
    http.HandleFunc("/debug/pprof/cmdline", Cmdline)
    http.HandleFunc("/debug/pprof/profile", Profile)
    http.HandleFunc("/debug/pprof/symbol", Symbol)
    http.HandleFunc("/debug/pprof/trace", Trace)
}

我们看到该包的init函数向http包的默认请求路由器DefaultServeMux注册了多个服务端点和对应的处理函数。而正是通过这些服务端点，我们可以在该独立程序运行期间获取各种类型的性能采集数据。现在打开浏览器，访问http://localhost:8080/debug/pprof/，我们就可以看到如图47-2所示的页面。

图47-2　net/http/pprof提供的性能采集页面

这个页面里列出了多种类型的性能采集数据，点击其中任何一个即可完成该种类型性能数据的一次采集。profile是CPU类型数据的服务端点，点击该端点后，该服务默认会发起一次持续30秒的性能采集，得到的数据文件会由浏览器自动下载到本地。如果想自定义采集时长，可以通过为服务端点传递时长参数实现，比如下面就是一个采样60秒的请求：

http://localhost:8080/debug/pprof/profile?seconds=60

如果独立程序的代码中没有使用http包的默认请求路由器DefaultServeMux，那么我们就需要重新在新的路由器上为pprof包提供的性能数据采集方法注册服务端点，就像下面的示例一样：

// chapter8/sources/pprof_standalone3.go
...
func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/debug/pprof/", pprof.Index)
    mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
    ...
    mux.HandleFunc("/hello", http.HandlerFunc(func(w http.ResponseWriter,
        r *http.Request) {
        fmt.Println(*r)
        w.Write([]byte("hello"))
    }))
    s := http.Server{
        Addr:    "localhost:8080",
        Handler: mux,
    }
    c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
    go func() {
        <-c
        s.Shutdown(context.Background())
    }()
    log.Println(s.ListenAndServe())
}

如果是非HTTP服务程序，则在导入包的同时还需单独启动一个用于性能数据采集的goroutine，像下面这样：

// chapter8/sources/pprof_standalone4.go

...
func main() {
    go func() {
        // 单独启动一个HTTP server用于性能数据采集
        fmt.Println(http.ListenAndServe("localhost:8080", nil))
    }()
    ...
}

通过上面几个示例我们可以看出，相比第一种方式，导入net/http/pprof包进行独立程序性能数据采集的方式侵入性更小，代码也更为独立，并且无须停止程序，通过预置好的各类性能数据采集服务端点即可随时进行性能数据采集。

3．性能数据的剖析

Go工具链通过pprof子命令提供了两种性能数据剖析方法： 命令行交互式 和 Web图形化 。命令行交互式的剖析方法更常用，也是基本的性能数据剖析方法；而基于Web图形化的剖析方法在剖析结果展示上更为直观。

（1）命令行交互方式

可以通过下面三种方式执行go tool pprof以进入采用命令行交互式的性能数据剖析环节：

$go tool pprof xxx.test cpu.prof // 剖析通过性能基准测试采集的数据
$go tool pprof standalone_app cpu.prof // 剖析独立程序输出的性能采集数据
// 通过net/http/pprof注册的性能采集数据服务端点获取数据并剖析
$go tool pprof http://localhost:8080/debug/pprof/profile

下面以pprof_standalone1.go这个示例的性能采集数据为例，看一下在命令行交互式的剖析环节，有哪些常用命令可用。首先生成CPU类型性能采集数据：

$go build -o pprof_standalone1 pprof_standalone1.go
$./pprof_standalone1 -cpuprofile pprof_standalone1_cpu.prof
^Cprogram exit

通过go tool pprof命令进入命令行交互模式：

$ go tool pprof pprof_standalone1 pprof_standalone1_cpu.prof
File: pprof_standalone1
Type: cpu
Time: ...
Duration: 16.14s, Total samples = 240ms ( 1.49%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

从pprof子命令的输出中我们看到：程序运行16.14s，采样总时间为240ms，占总时间的1.49%。

命令行交互方式下最常用的命令是topN（N为数字，如果不指定，默认等于10）：

(pprof) top
Showing nodes accounting for 240ms, 100% of 240ms total
Showing top 10 nodes out of 29
      flat  flat%   sum%        cum   cum%
      90ms 37.50% 37.50%       90ms 37.50%  runtime.nanotime1
      50ms 20.83% 58.33%       50ms 20.83%  runtime.pthread_cond_wait
      40ms 16.67% 75.00%       40ms 16.67%  runtime.usleep
      20ms  8.33% 83.33%       20ms  8.33%  runtime.asmcgocall
      20ms  8.33% 91.67%       20ms  8.33%  runtime.kevent
      10ms  4.17% 95.83%       10ms  4.17%  runtime.pthread_cond_signal
      10ms  4.17%   100%       10ms  4.17%  runtime.pthread_cond_timedwait_
                                                relative_np
         0     0%   100%       10ms  4.17%  main.main.func1
         0     0%   100%       30ms 12.50%  runtime.checkTimers
         0     0%   100%      130ms 54.17%  runtime.findrunnable
(pprof)

topN命令的输出结果默认按flat(flat%)从大到小的顺序输出。

flat列的值表示函数自身代码在数据采样过程中的执行时长。
flat%列的值表示函数自身代码在数据采样过程中的执行时长占总采样执行时长的百分比。
sum%列的值是当前行flat%值与排在该值前面所有行的flat%值的累加和。以第三行的sum%值75.00%为例，该值由前三行flat%累加而得，即16.67% + 20.83% + 37.50% = 75.00%。
cum列的值表示函数自身在数据采样过程中出现的时长，这个时长是其自身代码执行时长及其等待其调用的函数返回所用时长的总和。越是接近函数调用栈底层的代码，其cum列的值越大。
cum%列的值表示该函数cum值占总采样时长的百分比。比如：runtime.findrunnable函数的cum值为130ms，总采样时长为240ms，则其cum%值为两者的比值百分化后的值。

命令行交互模式也支持按cum值从大到小的顺序输出采样结果：

(pprof) top -cum
Showing nodes accounting for 90ms, 37.50% of 240ms total
Showing top 10 nodes out of 29
      flat  flat%   sum%        cum   cum%
         0     0%     0%      140ms 58.33%  runtime.mcall
         0     0%     0%      140ms 58.33%  runtime.park_m
         0     0%     0%      140ms 58.33%  runtime.schedule
         0     0%     0%      130ms 54.17%  runtime.findrunnable
         0     0%     0%       90ms 37.50%  runtime.nanotime (inline)
      90ms 37.50% 37.50%       90ms 37.50%  runtime.nanotime1
         0     0% 37.50%       70ms 29.17%  runtime.mstart
         0     0% 37.50%       70ms 29.17%  runtime.mstart1
         0     0% 37.50%       70ms 29.17%  runtime.sysmon
         0     0% 37.50%       60ms 25.00%  runtime.semasleep
(pprof)

在命令行交互模式下，可以通过list命令列出函数对应的源码，比如列出main.main函数的源码：

(pprof) list main.main
Total: 240ms
ROUTINE ======================== main.main.func1 in chapter8/sources/pprof_standalone1.go
         0       10ms (flat, cum)  4.17% of Total
         .          .     86:                       s2 := "gopher"
         .          .     87:                       s3 := "!"
         .          .     88:                       _ = s1 + s2 + s3
         .          .     89:                   }
         .          .     90:
         .       10ms     91:                   time.Sleep(10 * time.Millisecond)
         .          .     92:           }
         .          .     93:    }()
         .          .     94:    wg.Wait()
         .          .     95:    fmt.Println("program exit")
         .          .     96:}
(pprof)

我们看到，在展开源码的同时，pprof还列出了代码中对应行的消耗时长（基于采样数据）。可以选择耗时较长的函数，进一步向下展开，这个过程类似一个对代码进行向下钻取的过程，直到找到令我们满意的结果（某个导致性能瓶颈的函数中的某段代码）：

(pprof) list time.Sleep
Total: 240ms
ROUTINE ======================== time.Sleep in go1.14/src/runtime/time.go
         0       10ms (flat, cum)  4.17% of Total
         .          .    192:           t = new(timer)
         .          .    193:           gp.timer = t
         .          .    194:    }
         .          .    195:    t.f = goroutineReady
         .          .    196:    t.arg = gp
         .       10ms    197:    t.nextwhen = nanotime() + ns
         .          .    198:    gopark(resetForSleep, unsafe.Pointer(t), waitReasonSleep, traceEvGoSleep, 1)
         .          .    199:}
         .          .    200:
(pprof)

在命令行交互模式下，还可以生成CPU采样数据的函数调用图，且可以导出为多种格式，如PDF、PNG、JPG、GIF、SVG等。不过要做到这一点，前提是本地已安装图片生成所依赖的插件 graphviz 。

如下导出一幅PNG格式的图片：

(pprof) png
Generating report in profile001.png

png命令在当前目录下生成了一幅名为profile001.png的图片文件，如图47-3所示。

图47-3　pprof_standalone1采样数据生成的函数调用图

在图47-3中，我们可以清晰地看到cum%较大的叶子节点（用黑色粗体标出，叶子节点的cum%值与flat%值相等），它们就是我们需要重点关注的优化点。

在命令行交互模式下，通过web命令还可以在输出SVG格式图片的同时自动打开本地浏览器展示该图片。要实现这个功能也有一个前提，那就是本地SVG文件的默认打开应用为浏览器，否则生成的SVG文件很可能会以其他文本形式被其他应用打开。

（2）Web图形化方式

对于喜好通过图形化交互（GUI）方式剖析程序性能的开发者，go tool pprof提供了基于Web的图形化呈现所采集性能数据的方式。对于已经生成好的各类性能采集数据文件，我们可以通过下面的命令行启动一个Web服务并自动打开本地浏览器、进入图形化剖析页面（见图47-4）：

$go tool pprof -http=:9090 pprof_standalone1_cpu.prof
Serving web UI on http://localhost:9090

图形化剖析页面的默认视图（VIEW）是Graph，即函数调用图。在图47-4左上角的VIEW下拉菜单中，还可以看到Top、Source、Flame Graph等菜单项。

图47-4　go tool pprof自动打开本地浏览器并进入图形化剖析页面

Top视图等价于命令行交互模式下的topN命令输出（见图47-5）。

图47-5　图形化剖析页面的Top视图

Source视图等价于命令行交互模式下的list命令输出（见图47-6），只是这里将所有采样到的函数相关源码全部在一个页面列出了。

图47-6　图形化剖析页面的Source视图

Flame Graph视图即火焰图，该类型视图由性能架构师Brendan Gregg发明，并在近几年被广大开发人员接受。Go 1.10版本在go工具链中添加了对火焰图的支持。通过火焰图（见图47-7），我们可以快速、准确地识别出执行最频繁的代码路径，因此它多用于对CPU类型采集数据的辅助剖析（其他类型的性能采样数据也有对应的火焰图，比如内存分配）。

图47-7　图形化剖析页面的Flame Graph视图

go tool pprof在浏览器中呈现出的火焰图与标准火焰图有些差异：它是倒置的，即调用栈最顶端的函数在最下方。在这样一幅倒置火焰图中，y轴表示函数调用栈，每一层都是一个函数。调用栈越深，火焰越高。倒置火焰图每个函数调用栈的最下方就是正在执行的函数，上方都是它的父函数。

火焰图的x轴表示抽样数量，如果一个函数在x轴上占据的宽度越宽，就表示它被抽样到的次数越多，即执行的时间越长。倒置火焰图就是看最下面的哪个函数占据的宽度最大，这样的函数可能存在性能问题。

当鼠标悬浮在火焰图中的任意一个函数上时，图上方会显示该函数的性能采样详细信息。在火焰图中任意点击某个函数栈上的函数，火焰图都会水平局部放大，该函数会占据所在层的全部宽度，显示更为详细的信息。再点击root层或REFINE下拉菜单中的Reset可恢复火焰图原来的样子。

对于通过net/http/pprof暴露性能数据采样端点的独立程序，同样可以采用基于Web的图形化页面进行性能剖析。以pprof_standalone4.go的剖析为例：

// 启动pprof_standalone4.go
$go run pprof_standalone4.go

// 启动Web图形化剖析
$go tool pprof -http=:9090 http://localhost:8080/debug/pprof/profile
Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile
Saved profile in /Users/tonybai/pprof/pprof.samples.cpu.001.pb.gz
Serving web UI on http://localhost:9090

执行go tool pprof时，pprof会对pprof_standalone4.go进行默认30秒的CPU类型性能数据采样，然后将采集的数据下载到本地，存为pprof.samples.cpu.001.pb.gz，之后go tool pprof加载pprof.samples.cpu.001.pb.gz并自动启动浏览器进入性能剖析默认页面（函数调用图），如图47-8所示。

图47-8　针对采用net/http/pprof的独立程序的Web图形化剖析页面

剩下的操作和之前描述的完全一致，这里就不赘述了。

47.1 pprof的工作原理