golang的pprof与火焰图实战

无标签
golang
发布日期:   2021-07-18
更新日期:   2022-09-07
文章字数:   11.2k
阅读时长:   43 分
阅读次数:  

1 前言

声明：本文参考这篇文章，自己跟着做了一遍，记录一下，然后补充了火焰图的使用。

https://blog.wolfogre.com/posts/go-ppof-practice/

https://www.liwenzhou.com/posts/Go/performance_optimisation/#autoid-1-5-2

https://blog.wolfogre.com/posts/go-ppof-practice/

https://github.com/wolfogre/blog-utterances/issues/39

https://golang2.eddycjy.com/posts/ch6/01-pprof-1/

https://github.com/eddycjy/blog

https://github.com/brendangregg/FlameGraph/blob/master/README.md

[鸟窝]-[译] Go 可视化性能分析工具

https://www.cnblogs.com/jiujuan/p/14604609.html

1.1 性能分析

在软件工程中，性能分析（Performance Analysis，也称为Profiling），是以收集程序运行时信息为手段研究程序行为的分析方法，是一种动态程序分析方法

–维基百科

在日常开发中，性能优化往往是一个长期的事情，在业务的不同阶段，会遇到各种各样的性能问题，迅速分析并定位程序的性能瓶颈，能让我们付出最小的努力，得到最大的回报。

1.2 代码开发上线步骤

  1. 上线前

    a. 压测：我们通过压测可以获知系统的性能，例如每秒能处理的请求数，平均响应时间，错误率等指标。这样，我们对自己服务的性能算是有个底。

    b. 问题：但是压测是线下的模拟流量，如果到了线上呢？会遇到高并发、大流量，不靠谱的上下游，突发的尖峰流量等等场景，这些都是不可预知的。

  2. 上线后

    1. 线上突然大量报警，接口超时，错误数增加
    2. 终极解决方案：看日志、看监控；使用性能分析工具分析程序的性能，找到瓶颈
    3. 临时解决方案：首先要降级、限流、回滚，先止损

  3. 总结

    1. 性能分析很重要，尤其是要统计好性能数据，出问题了，可以随时拿出来看。

根据上面内容引出了性能分析，性能分析主要关注 CPU、内存、磁盘 IO、网络这些指标。

在软件工程中，性能分析（performance analysis，也称为 profiling），是以收集程序运行时信息为手段研究程序行为的分析方法，是一种动态程序分析的方法。

profiling 是指在程序执行过程中，收集能够反映程序执行状态的数据。

一般常规分析内容：

  1. cpu：程序对cpu的使用情况 - 使用时长，占比等
  2. 内存：程序对cpu的使用情况 - 使用时长，占比，内存泄露等。如果在往里分，程序堆、栈使用情况
  3. I/O：IO的使用情况 - 哪个程序IO占用时间比较长

golang 程序中分析内容：

  1. goroutine：go的协程使用情况，调用链的情况
  2. goroutine leak：goroutine泄露检查
  3. go dead lock：死锁的检测分析
  4. data race detector：数据竞争分析，其实也与死锁分析有关

1.3 golang 性能调试优化方法

比如 linux 中 cpu 性能调试，工具有 top，dstat，perf 等。

那么在 golang 中，有哪些分析方法？

golang 性能调试优化方法：

  • Benchmark：基准测试，对特定代码的运行时间和内存信息等进行测试
  • Profiling：程序分析，程序的运行画像，在程序执行期间，通过采样收集的数据对程序进行分析
  • Trace：跟踪，在程序执行期间，通过采集发生的事件数据对程序进行分析

profiling 和 trace 有啥区别？
profiling 分析没有时间线，trace 分析有时间线。

在 golang 中，应用方法的工具呢？

这里介绍 pprof 这个 golang 工具，它可以帮助我们调试优化程序。

它的最原始程序是 gperftools - https://github.com/gperftools/gperftools，golang 的 pprof 是从它而来的。

2 pprof 是什么

在 Go 语言中，pprof 是用于可视化和分析性能分析数据的工具，pprof 以 profile.proto 读取分析样本的集合，并生成报告以可视化并帮助分析数据（支持文本和图形报告）。

而刚刚提到的 profile.proto 是一个 Protobuf v3 的描述文件，它描述了一组 callstack 和 symbolization 信息， 作用是统计分析的一组采样的调用栈，是很常见的 stacktrace 配置文件格式。

一句话描述：Golang自带的一款开箱即用的性能监控和分析工具。

3 pprof 作用

go的pprof提供了2个工具供我们使用，runtime/pprof中是它的源码，net/http/pprof对源码做了简单封装，能让你在http服务中直接使用。

它可以采样程序运行时的CPU、堆内存、Goroutine、锁竞争、阻塞调用、系统线程的使用情况。然后通过可视化终端或网页的形式展示给用户，用户可以通过列表、调用图、源码、火焰图、反汇编等视图去展示采集到的性能指标

pprof 作用

3.1 pprof指标采样的维度

  1. CPU（profile）
    1. CPU Profiling：CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置。
    2. 报告CPU的使用情况，定位到热点（消耗CPU周期最多的）代码。默认情况下Go以100HZ的频率进行CPU采样
  2. Goroutine
    1. Goroutine Profiling： Goroutine 分析，可以对当前应用程序正在运行的 Goroutine 进行堆栈跟踪和分析。这项功能在实际排查中会经常用到，因为很多问题出现时的表象就是 Goroutine 暴增，而这时候我们要做的事情之一就是查看应用程序中的 Goroutine 正在做什么事情，因为什么阻塞了，然后再进行下一步。
  3. 系统线程
    1. 获取导致创建 OS 线程的 goroutine 堆栈
  4. 堆内存/内存剖析（heap）
    1. Memory Profiling：内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏。
    2. 包含每个 goroutine 分配大小，分配堆栈等。
    3. 每分配 runtime.MemProfileRate(默认为512K) 个字节进行一次数据采样。
  5. 内存剖析（allocs）：报告所有内存分配历史
  6. 阻塞操作
    1. Block Profiling：阻塞分析，记录 Goroutine 阻塞等待同步（包括定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置。
    2. 获取导致阻塞的 goroutine 堆栈(如 channel, mutex 等)，使用前需要先调用 runtime.SetBlockProfileRate
  7. 锁竞争
    1. Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置。
  8. 执行追踪（trace）：追踪当前应用程序的执行栈

3.2 原理

3.2.1 CPU采样

CPU采样会记录所有的调用栈和它们的占用时间。

在采样时，进程会每秒暂停一百次，每次会记录当前的调用栈信息。

汇总之后，根据调用栈在采样中出现的次数来推断函数的运行时间。 你需要手动地启动和停止采样。每秒100次的暂停频率也不能更改。

这个定时暂停机制在unix或类unix系统上是依赖信号机制实现的。

每次「暂停」都会接收到一个信号，通过系统计时器来保证这个信号是固定频率发送的。 接下来看看具体的流程。

一共有三个相关角色：进程本身、操作系统和写缓冲。

启动采样时，进程向OS注册一个定时器，OS会每隔10ms向进程发送一个SIGPROF信号，进程接收到信号后就会对当前的调用栈进行记录。

与此同时，进程会启动一个写缓冲的goroutine，它会每隔100ms从进程中读取已经记录的堆栈信息，并写入到输出流。

当采样停止时，进程向OS取消定时器，不再接收信号，写缓冲读取不到新的堆栈时，结束输出。

采样对象：函数调用和它们的占用时间

采样率：100次/秒

固定值采样时间：从手动启动到手动结束

  • 操作系统：每10ms向进程发送一次SIGPROF信号
  • 进程：每次接收到SIGPROF会记录调用栈
  • 写缓冲：每100ms读取一次已经记录的调用栈并写入输出流
image-20210801222450112 image-20210801222823463

3.2.2 Goroutine & ThreadCreate采样

接下来我们来看看goroutine和系统线程的采样。这两个采样指标在概念上和实现上都比较相似，所以在这里进行对比。

Goroutine采样会记录所有用户发起，也就是入口不是runtime开头的goroutine，以及main函数所在goroutine的信息和创建这些goroutine的调用栈；

ThreadCreate采样会记录由程序创建的所有系统线程的信息和调用栈。

他们在实现上非常的相似，都是会在STW之后，遍历所有goroutine/所有线程的列表（图中的m就是GMP模型中的m，在golang中和线程一一对应），并输出堆栈，最后Start The World继续运行。

这个采样是立刻触发的全量记录，你可以通过比较两个时间点的差值来得到某一时间段的指标。

Goroutine：记录所有用户发起且在运行中的goroutine（即入口非runtime开头的）和runtime.main的调用栈信息

ThreadCreate：记录程序创建的所有系统线程的信息

3.2.3 Heap（堆内存）采样

接下来看看堆内存采样。 我在提到内存指标的时候说的都是「堆内存」而不是「内存」，这是因为pprof的内存采样是有局限性的。

内存采样在实现上依赖了内存分配器的记录，所以它只能记录在堆上分配，且会参与GC的内存，一些其他的内存分配，例如调用结束就会回收的栈内存、一些更底层使用cgo调用分配的内存，是不会被内存采样记录的。

它的采样率是一个大小，默认每分配512KB内存会采样一次，采样率是可以在运行开头调整的，设为1则为每次分配都会记录。

与CPU和goroutine都不同的是，内存的采样是一个持续的过程，它会记录从程序运行起的所有分配或释放的内存大小和对象数量，并在采样时遍历这些结果进行汇总。

还记得刚才的例子中，堆内存采样的四种指标吗？alloc的两项指标是从程序运行开始的累计指标，而inuse的两项指标是通过累计分配减去累计释放得到的程序当前持有的指标。

你也可以通过比较两次alloc的差值来得到某一段时间程序分配的内存【大小和数量】

采样程序通过内存分配器在堆上分配和释放的内存，记录分配/释放的大小和数量

采样率：每分配512KB记录一次，可在运行开头修改，1为每次分配均记录

采样时间：从程序运行开始到采样时

采样指标：alloc_space, alloc_objects, inuse_space, inuse_objects

计算方式：inuse=alloc-free

3.2.4 Block(阻塞) & Mutex(锁竞争)采样

讲完了堆内存，还剩下阻塞和锁竞争这两种采样。 这两个指标在流程和原理上也非常相似，我在这里也做了一个对比。

这两个采样记录的都是对应操作发生的调用栈、次数和耗时，不过这两个指标的采样率含义并不相同。

阻塞操作的采样率是一个「阈值」，消耗超过阈值时间的阻塞操作才会被记录，1为每次操作都会记录。

锁竞争的采样率是一个「比例」，运行时会通过随机数来只记录固定比例的锁操作，1为每次操作都会记录。

它们在实现上也是基本相同的。都是一个「主动上报」的过程。

在阻塞操作或锁操作发生时，会计算出消耗的时间，连同调用栈一起主动上报给采样器，采样器会根据采样率可能会丢弃一些记录。

在采样时，采样器会遍历已经记录的信息，统计出具体操作的次数、调用栈和总耗时。和堆内存一样，你可以对比两个时间点的差值计算出段时间内的操作指标。

阻塞操作

采样阻塞操作的次数和耗时

采样率：阻塞耗时超过阈值的才会被记录，1为每次阻塞均记录

锁竞争

采样争抢锁的次数和耗时

采样率：只记录固定比例的锁操作，1为每次加锁均记录

4 pprof 使用模式

  • Report generation：报告生成
  • Interactive terminal use：交互式终端
  • Web interface：Web 界面

5 采样方式

方式名称 如何使用 优点 缺点 使用场景
runtime/pprof 手动调用【runtime.StartCPUProfile、runtime.StopCPUProfile】等API来进行数据的采集。采集程序（非 Server）的指定区块的运行数据进行分析。 灵活性高、按需采集。 工具型应用（比如说定制化的分析小工具、集成到公司监控系统）。这种应用运行一段时间就结束。
net/http/pprof 通过http服务来获取Profile采样文件。 import _ "net/http/pprof"。基于 HTTP Server 运行，并且可以采集运行时数据进行分析。net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来 简单易用 在线服务（一直运行着的程序）
go test 通过命令go test -bench . -cpuprofile cpu.prof来进行采集数据。 针对性强、细化到函数 进行某函数的性能测试

上面的 pprof 开启后，每隔一段时间就会采集当前程序的堆栈信息，获取函数的 cpu、内存等使用情况。通过对采样的数据进行分析，形成一个数据分析报告。

pprof 以 profile.proto 的格式保存数据，然后根据这个数据可以生成可视化的分析报告，支持文本形式和图形形式报告。
profile.proto 里具体的数据格式是 protocol buffers。

那用什么方法来对数据进行分析，从而形成文本或图形报告？

用一个命令行工具 go tool pprof 。

5.1 go test

  • cpu 使用分析：-cpuprofile=cpu.pprof
  • 内存使用分析：-benchmem -memprofile=mem.pprof
  • block分析：-blockprofile=block.pprof

运行命令采样数据：


go test -bench=. -run=none -benchmem -memprofile=mem.pprof

go test -bench=. -run=none -blockprofile=block.pprof

go test -bench=. -run=none -benchmem -memprofile=mem.pprof -cpuprofile=cpu.pprof

go test -bench=. -run=none -benchmem -memprofile=mem.pprof -cpuprofile=cpu.pprof -blockprofile=block.pprof

5.2 runtime/pprof

除了注入 http handler 和 go test 以外，我们还可以在程序中通过 pprof 所提供的 Lookup 方法来进行相关内容的采集和调用，其一共支持六种类型，分别是：goroutine、threadcreate、heap、block、mutex，代码如下：

除了注入 http handler 和 go test 以外，我们还可以在程序中通过 pprof 所提供的 Lookup 方法来进行相关内容的采集和调用，其一共支持六种类型，分别是：goroutine、threadcreate、heap、block、mutex，代码如下：

type LookupType int8

const (
    LookupGoroutine LookupType = iota
    LookupThreadcreate
    LookupHeap
    LookupAllocs
    LookupBlock
    LookupMutex
)

func pprofLookup(lookupType LookupType, w io.Writer) error {
    var err error
    switch lookupType {
    case LookupGoroutine:
        p := pprof.Lookup("goroutine")
        err = p.WriteTo(w, 2)
    case LookupThreadcreate:
        p := pprof.Lookup("threadcreate")
        err = p.WriteTo(w, 2)
    case LookupHeap:
        p := pprof.Lookup("heap")
        err = p.WriteTo(w, 2)
    case LookupAllocs:
        p := pprof.Lookup("allocs")
        err = p.WriteTo(w, 2)
    case LookupBlock:
        p := pprof.Lookup("block")
        err = p.WriteTo(w, 2)
    case LookupMutex:
        p := pprof.Lookup("mutex")
        err = p.WriteTo(w, 2)
    }

    return err
}

接下来我们只需要对该方法进行调用就好了，其提供了 io.Writer 接口，也就是只要实现了对应的 Write 方法，我们可以将其写到任何支持地方去，如下：

...
func init() {
    runtime.SetMutexProfileFraction(1)
    runtime.SetBlockProfileRate(1)
}

func main() {
    http.HandleFunc("/lookup/heap", func(w http.ResponseWriter, r *http.Request) {
        _ = pprofLookup(LookupHeap, os.Stdout)
    })
    http.HandleFunc("/lookup/threadcreate", func(w http.ResponseWriter, r *http.Request) {
        _ = pprofLookup(LookupThreadcreate, os.Stdout)
    })
    http.HandleFunc("/lookup/block", func(w http.ResponseWriter, r *http.Request) {
        _ = pprofLookup(LookupBlock, os.Stdout)
    })
    http.HandleFunc("/lookup/goroutine", func(w http.ResponseWriter, r *http.Request) {
        _ = pprofLookup(LookupGoroutine, os.Stdout)
    })
    _ = http.ListenAndServe("0.0.0.0:6060", nil)
}

在上述代码中，我们将采集结果写入到了控制台上，我们可以进行一下验证，调用 http://127.0.0.1:6060/lookup/heap，控制台输出结果如下：

$ go run main.go
heap profile: 0: 0 [0: 0] @ heap/1048576

# runtime.MemStats
# Alloc = 180632
# TotalAlloc = 180632
# Sys = 69928960
# Lookups = 0
...

本章节所有测试都是使用的runtime_method.go文件，子章节只会展示我的测试代码，统一用一个入口main函数。

mian函数如下

package main

import (
    "fmt"
    "log"
    "os"
    "runtime"
    "runtime/pprof"
    "sync"
    "time"
)

func main() {
    // 设置最大的可同时使用的 CPU 核数。只有一个操作系统线程可供用户的Go代码使用
    runtime.GOMAXPROCS(1)

    CollectCpu()
    // CollectMutex()
    // CollectBlock()
    // CollectHeap()
    // CollectAllocs()
}

运行函数方法：执行命令,runtime_method.go是我的文件名


go run runtime_method.go

结果分析方式也是一样的，如下。

go tool pprof cpu.prof

执行命令行两件套
top
list 函数名

生成web页面查看
web

或者通过暴露http端口的方式，可以查看更多类型的图。

go tool pprof -http=:6060 cpu.prof
profile已经存在的文件

5.2.1 采集CPU(CPU 占用过高)


func CollectCpu() {

    // 创建分析文件，在当前目录下
    file, err := os.Create("./cpu.prof")
    if err != nil {
        fmt.Printf("创建采集文件失败, err:%v\n", err)
        return
    }

    // 进行cpu数据的获取
    pprof.StartCPUProfile(file)
    defer pprof.StopCPUProfile()

    // 执行一段有问题的代码
    for i := 0; i < 4; i++ {
        go do1()
    }
    time.Sleep(10 * time.Second)
}

5.2.2 采集内存(heap-内存占用过高)

作用：看哪些方法分配了最多的内存


const (
    Ki = 1024
    Mi = Ki * Ki
    Gi = Ki * Mi
    Ti = Ki * Gi
    Pi = Ki * Ti
)

type Mouse struct {
    buffer [][Mi]byte
}

func (m *Mouse)StealMem() {
    max := Gi
    for len(m.buffer) * Mi < max {
        m.buffer = append(m.buffer, [Mi]byte{})
    }
}

func CollectHeap()  {
    // 设置采样率，默认每分配512*1024字节采样一次。如果设置为0则禁止采样，只能设置一次
    runtime.MemProfileRate = 512 * 1024

    f, err := os.Create("./heap.prof")
    if err != nil {
        log.Fatal("could not create heap profile: ", err)
    }
    defer f.Close()

    // 高的内存占用 : 有个循环会一直向 m.buffer 里追加长度为 1 MiB 的数组，直到总容量到达 1 GiB 为止，且一直不释放这些内存，这就难怪会有这么高的内存占用了。
    m := &Mouse{}
    m.StealMem()

    // runtime.GC() // 执行GC，避免垃圾对象干扰

    // 将剖析概要信息记录到文件
    if err := pprof.WriteHeapProfile(f); err != nil {
        log.Fatal("could not write heap profile: ", err)
    }

}

5.2.3 采集内存(allocs-频繁内存回收)

获取程序运行依赖，所有内存分配的历史


func ApplyMemDoNothing() {
    // 在 golang 里，对象是使用堆内存还是栈内存，由编译器进行逃逸分析并决定，如果对象不会逃逸，便可在使用栈内存，
    // 但总有意外，就是对象的尺寸过大时，便不得不使用堆内存。所以这里设置申请 16 MiB 的内存就是为了避免编译器直接在栈上分配，如果那样得话就不会涉及到 GC 了。
    _ = make([]byte, 16 * Mi)
}

func CollectAllocs() {
    // 设置采样率，默认每分配512*1024字节采样一次。如果设置为0则禁止采样，只能设置一次
    runtime.MemProfileRate = 512 * 1024

    f, err := os.Create("./allocs.prof")
    if err != nil {
        log.Fatal("could not create memory profile: ", err)
    }
    defer f.Close()

    // 频繁内存回收
    for i := 0; i < 100; i++ {
        time.Sleep(3 * time.Second)
        ApplyMemDoNothing()
    }

    // runtime.GC() // 执行GC，避免垃圾对象干扰

    // 将剖析概要信息记录到文件
    if err := pprof.Lookup("allocs").WriteTo(f, 0); err != nil {
        log.Fatal("could not write allocs profile: ", err)
    }

}

为了获取程序运行过程中 GC 日志，我们需要先退出炸弹程序，再在重新启动前赋予一个环境变量，同时为了避免其他日志的干扰，使用 grep 筛选出 GC 日志查看：

由于内存的申请与释放频度是需要一段时间来统计的，所有我们保证炸弹程序已经运行了几分钟之后，再结束：

go build runtime_method.go
GODEBUG=gctrace=1 ./runtime_method | grep gc

allocs执行结果

可以看到，GC 差不多每 3 秒就发生一次，且每次 GC 都会从 16MB 清理到几乎 0MB，说明程序在不断的申请内存再释放，这是高性能 golang 程序所不允许的。

如果你希望进一步了解 golang 的 GC 日志可以查看《如何监控 golang 程序的垃圾回收》,为保证实验节奏，这里不做展开。

所以接下来使用 pprof 排查时，我们在乎的不是什么地方在占用大量内存，而是什么地方在不停地申请内存，这两者是有区别的。

image-20210801182209809

5.2.4 采集goroutine(协程泄露)


func CollectGoroutine() {
    f, err := os.Create("./goroutine.prof")

    if err != nil {
        log.Fatal("could not create goroutine profile: ", err)
    }
    defer f.Close()

    // 函数每次释放 10 个协程出去，每个协程会睡眠 30 秒再退出，而 Drink 函数又会被反复调用
    // 这才导致大量协程泄露，试想一下，如果释放出的协程会永久阻塞，那么泄露的协程数便会持续增加，
    // 内存的占用也会持续增加，那迟早是会被操作系统杀死的。

    for i := 0; i < 1000; i++ {
        go func() {
            time.Sleep(10 * time.Second)
        }()
    }

    // 等待所有协程运行结束
    //time.Sleep(100 * time.Second)

    if err = pprof.Lookup("goroutine").WriteTo(f, 0); err != nil {
        fmt.Fprintf(os.Stderr, "Can not write %s: %s", "./goroutine.prof", err)
    }

}


func main() {
    // 设置最大的可同时使用的 CPU 核数。只有一个操作系统线程可供用户的Go代码使用
    runtime.GOMAXPROCS(1)

    // CollectCpu()
    // CollectMutex()
    // CollectBlock()
    // CollectHeap()

    go func() {
        if err := http.ListenAndServe(":6060", nil); err != nil {
            log.Fatal(err)
        }
        os.Exit(0)
    }()

    for {
        CollectGoroutine()
        time.Sleep(3 * time.Second)
    }

}

goroutine执行结果

在调用栈上来讲，其展示顺序是自下而上的，也就是 runtime.main 方法调用了 main.main 方法，main.main 方法又调用了 net/http.ListenAndServe 方法，这里对应的也就是我们所使用的示例代码了，排查起来会非常方便。

每个调用堆栈信息用 ----------- 分割，函数方法前的就是指标数据，像 Goroutine Profiling 展示是就是该方法占用的 goroutine 的数量。而 Heap Profiling 展示的就是占用的内存大小，如下：

traces使用

5.2.5 采集mutex(锁的争用)


func CollectMutex()  {
    // 进行采集量的设置，否则默认关闭，若设置的值小于等于 0 也会认为是关闭。
    // 一般有如下方式：调用 chan（通道）、调用 sync.Mutex （同步锁）、调用 time.Sleep() 等等。
    runtime.SetMutexProfileFraction(1)

    f, err := os.Create("./mutex.prof")

    if err != nil {
        log.Fatal("could not create memory profile: ", err)
    }
    defer f.Close()

    // 这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，
    // 但由于子协程足足睡眠了3秒，导致主协程等待这个锁释放足足等了一秒钟。
    m := &sync.Mutex{}
    m.Lock()
    go func() {
        time.Sleep(3 * time.Second)
        m.Unlock()
    }()
    m.Lock()

    time.Sleep(10 * time.Second)

    // 将阻塞剖析概要信息记录到文件
    if err = pprof.Lookup("mutex").WriteTo(f, 0); err != nil {
        fmt.Fprintf(os.Stderr, "Can not write %s: %s", "./mutex.prof", err)
    }

}

5.2.6 采集block(阻塞操作)


func CollectBlock()  {
    // 参数5表示，每发生1次Goroutine阻塞事件则采样一次。默认值1。
    runtime.SetBlockProfileRate(1)

    f, err := os.Create("./block.prof")
    if err != nil {
        log.Fatal("could not create block profile: ", err)
    }
    defer f.Close()

    // 不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。
    <- time.After(time.Second)

    // 将阻塞剖析概要信息记录到文件
    if err = pprof.Lookup("block").WriteTo(f, 0); err != nil {
        fmt.Fprintf(os.Stderr, "Can not write %s: %s", "./block.prof", err)
    }

}

5.3 net/http/pprof

上代码

package main

import (
    "fmt"
    "net/http"
    _ "net/http/pprof"  // 第一步～
)

// 一段有问题的代码
func do() {
    var c chan int
    for {
        select {
        case v := <-c:
            fmt.Printf("我是有问题的那一行，因为收不到值：%v", v)
        default:
        }
    }
}

func main() {
    // 执行一段有问题的代码
    for i := 0; i < 4; i++ {
        go do()
    }
    http.ListenAndServe("127.0.0.1:9090", nil)
}

通过代码中的关键两步，执行起来就可以通过 http://127.0.0.1:9090/debug/pprof/看到对应的数据啦～

http方式的结果

6 采样的数据内容

不管是前文哪种方式获取，都可以进行分析。这里http的方式把可以看到的信息全部都列出来了。

类型 描述 url
allocs 内存分配情况的采样信息，过去所有内存抽样情况 $host/debug/pprof/allocs?debug=1
blocks 阻塞操作情况的采样信息，同步阻塞时程序栈跟踪的一些情况 $host/debug/pprof/block?debug=1
cmdline 显示程序启动命令参数及其参数
goroutine 显示当前所有协程的堆栈信息
heap 堆上的内存分配情况的采样信息，活动对象的内存分配情况 $host/debug/pprof/heap?debug=1
mutex 锁竞争情况的采样信息，互斥锁持有者的栈帧情况 $host/debug/pprof/mutex?debug=1
profile cpu占用情况的采样信息，点击会下载文件，cpu profile，点击时会得到一个文件，然后可以用 go tool pprof 命令进行分析 $host/debug/pprof/profile
threadcreate 系统线程创建情况的采样信息，创建新 OS 线程的堆栈跟踪情况 $host/debug/pprof/threadcreate?debug=1
trace 程序运行跟踪信息，当前程序执行的追踪情况，点击时会得到一个文件，可以用 go tool trace 命令来分析这个文件 $host/debug/pprof/trace

通过加粗的关键字，很直观可以看到能分析到的数据。

（后文将重点根据cpu的采样信息展开命令行和图形化页面的讨论，其余项将在实战中应用）

7 数据分析方式

7.1 命令行

核心命令：go tool pprof <binary> <source>

binary：是应用的二进制文件，用来解析各种符号；

source：代表生成的分析数据来源，可以是本地文件（前文生成的cpu.prof），也可以是http地址（比如：go tool pprof http://127.0.0.1:9090/debug/pprof/profile）

需要注意的是：较大负载的情况下（要不就故意写故障代码，或者就模拟访问压力）获取的有效数据更有意义，如果处于空闲状态，得到的结果可能意义不大

例子如下

go build -o havlak1 havlak1.go 
go tool pprof havlak1 havlak1.prof

通过工具go tool pprof打开URL或文件后，会显示一个 (pprof)提示符，你可以使用以下命令：

命令 参数 说明
gv [focus] 将当前概要文件以图形化和层次化的形式显示出来。当没有任何参数时，在概要文件中的所有采样都会被显示如果指定了focus参数，则只显示调用栈中有名称与此参数相匹配的函数或方法的采样。 focus参数应该是一个正则表达式需要dot、gv命令，执行下面的命令安装：Shell12sudo apt-get install graphvizsudo apt-get install gv
web [focus] 生成 svg 热点图片，与gv命令类似，web命令也会用图形化的方式来显示概要文件。但不同的是，web命令是在一个Web浏览器中显示它
list [routine_regexp] 列出名称与参数 routine_regexp代表的正则表达式相匹配的函数或方法的相关源代码
weblist [routine_regexp] 在Web浏览器中显示与list命令的输出相同的内容。它与list命令相比的优势是，在我们点击某行源码时还可以显示相应的汇编代码
top[N] [–cum] top命令可以以本地采样计数为顺序列出函数或方法及相关信息如果存在标记 –cum则以累积采样计数为顺序默认情况下top命令会列出前10项内容。但是如果在top命令后面紧跟一个数字，那么其列出的项数就会与这个数字相同。默认显示 flat 前10的函数调用，可使用 -cum 以 cum 排序
traces 打印所有采集的样本
disasm [routine_regexp] 显示名称与参数 routine_regexp相匹配的函数或方法的反汇编代码。并且，在显示的内容中还会标注有相应的采样计数
callgrind [filename] 利用callgrind工具生成统计文件。在这个文件中，说明了程序中函数的调用情况。如果未指定 filename参数，则直接调用kcachegrind工具。kcachegrind可以以可视化的方式查看callgrind工具生成的统计文件
help 显示帮助
quit 退出

开始分析前文生成的cpu.prof:

go tool pprof cpu.prof

go tool pprof cpu.prof

类型 描述 举例
flat 该函数占用CPU的耗时，不包含当前函数调用其它函数并等待返回的时间 selectnbrecv占用CPU的耗时是12.29s
flat% 该函数占用CPU的耗时的百分比 selectnbrecv耗时：12.29s，cpu总耗时：29.14，12.29/29.14=42.18
sum% 前面所有flat总和，top命令中排在它上面的函数以及本函数flat%之和 chanrecv：42.18%+30.47% = 72.65%
cum 当前函数加上该函数调用其它函数的累计CPU耗时，该指标包含子函数耗时 chanrecv：8.88+0.54=9.42
cum% 当前函数加上该函数调用其它函数的累计CPU耗时的百分比 9.42/29.14=32.33%
最后一列 当前函数名称 -

什么时候Flat==cum？Flat是当前函数耗时，Cum是当前函数和调用函数累计耗时，他俩相等，代表当前函数没有调用别的函数。

什么时候Flat==0？函数中只有其它函数的调用。

上面的命令解析

发现do函数有点问题。此时通过命令：list funcName，来进行查看具体的位置

web

1.在前文的对话框中继续输入：web。即可生成pprof001.svg的页面。

2.执行命令：go tool pprof -pdf cpu.prof,会生成profile001.pdf的pdf文件。(参数可选text、pdf、svg)，不管哪种形式，都会得到以下图片：

web生成的图片

7.2 可视化界面方式

执行命令：go tool pprof -http=:6060 cpu.prof

http方式

汇总
  • Top （同前文gdb交互页面的top命令）

top

  • Graph（同前文gdb交互页面的web命令）

  • Flame Graph（火焰图）

    这里的颜色是随机分布的，只是看起来像火焰。

    调用顺序由上到下，每一块代表一个函数，越大代表占用 CPU 的时间更长。同时它也可以支持点击块深入进行分析。

Flame Graph

  • Peek（详细=树结构）

peek

  • Source（同前文gdb交互页面的list FuncName命令）

source

  • Disassemble

image-20210726105956501

8 数据分析实战

8.1 排查套路

8.1.1 套路1

这里先说一下排查套路。

第一步：进入排除对应的gdb交互。

go tool pprof http://localhost:6060/debug/pprof/{填上你想查看的内容}?seconds=10
  • seconds=10, 采样间隔时间数字

内容关键字：

类型 描述
allocs 内存分配情况的采样信息
blocks 阻塞操作情况的采样信息
cmdline 显示程序启动命令参数及其参数
goroutine 显示当前所有协程的堆栈信息
heap 堆上的内存分配情况的采样信息
mutex 锁竞争情况的采样信息
profile cpu占用情况的采样信息，点击会下载文件
threadcreate 系统线程创建情况的采样信息
trace 程序运行跟踪信息

第二步：三联招，top->list FuncName->web

通过占用比分析，查看具体代码行数，看大图确认。

第三步：解决问题。

（细心的同学可能会发现没有对trace进行分析，这个请期待《一看就懂系列之Golang的trace》）

8.1.2 套路2-推荐

将其重新运行起来，然后在其它窗口执行下述命令：

wget http://127.0.0.1:6060/debug/pprof/profile

默认需要等待 30 秒，执行完毕后可在当前目录下发现采集的文件 profile，针对可视化界面我们有两种方式可进行下一步分析：

该命令将在所指定的端口号运行一个 PProf 的分析用的站点。

go tool pprof -http=:6001 profile

8.2 背景说明

本章节使用WOLFOGRE的文章进行实践。

git clone github.com/wolfogre/go-pprof-practice
cd $GOPATH/src/github.com/wolfogre/go-pprof-practice
go mod init
go mod tidy
go mod download
go build
./go-pprof-practice

运行后注意查看一下资源是否吃紧，机器是否还能扛得住，坚持一分钟，如果确认没问题，咱们再进行下一步。


http://localhost:6060/debug/pprof/

image-20210801203418974

8.3 排查 CPU 占用过高

我们首先通过活动监视器（或任务管理器、top 命令，取决于你的操作系统和你的喜好），查看一下炸弹程序的 CPU 占用：

image-20210801204540416 

wget http://localhost:6060/debug/pprof/profile
go tool pprof -http=:8080 profile

image-20210801211815133

很明显，CPU 占用过高是 github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat 造成的。

可以看到，是第 24 行那个一百亿次空循环占用了大量 CPU 时间，至此，问题定位成功！

image-20210801213511656

接下来有一个扩展操作：图形化显示调用栈信息，这很酷，但是需要你事先在机器上安装 graphviz，大多数系统上可以轻松安装它：

brew install graphviz # for macos
apt install graphviz # for ubuntu
yum install graphviz # for centos

至此，这一小节使用 pprof 定位 CPU 占用的实验就结束了，你需要输入 exit 退出 pprof 的交互式终端。

为了方便进行后面的实验，我们修复一下这个问题，不用太麻烦，注释掉相关代码即可：

func (t *Tiger) Eat() {
    log.Println(t.Name(), "eat")
    //loop := 10000000000
    //for i := 0; i < loop; i++ {
    //    // do nothing
    //}
}

之后修复问题的的方法都是注释掉相关的代码，不再赘述。你可能觉得这很粗暴，但要知道，这个实验的重点是如何使用 pprof 定位问题，我们不需要花太多时间在改代码上。

8.4 排查内存占用过高

重新编译炸弹程序，再次运行，可以看到 CPU 占用率已经下来了，但是内存的占用率仍然很高：

image-20210801213859734

image-20210801214029301

可以看到这次出问题的地方在 github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal

注释代码就可以了

选项名 作用
alloc_objects 分析应用程序的内存临时分配情况
alloc_space 查看每个函数分配的内存空间大小
inuse_space 分析应用程序的常驻内存占用情况
inuse_objects 查看每个函数所分配的对象数量

执行该命令后，能够很快的拉取到其结果，因为它不需要像 CPU Profiling 做采样等待，这里需要注意的一点是 Type 这一个选项，你可以看到它默认显示的是 inuse_space，实际上可以针对多种内存概况进行分析，常用的类别如下：

  • inuse_space：分析应用程序的常驻内存占用情况。
⋊> ~/testpprof go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap                                                                                                              
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/xxx/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
Type: inuse_space
Time: Aug 1, 2021 at 9:41pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof)
(pprof) top
Showing nodes accounting for 1GB, 100% of 1GB total
      flat  flat%   sum%        cum   cum%
       1GB   100%   100%        1GB   100%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
         0     0%   100%        1GB   100%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
         0     0%   100%        1GB   100%  main.main
         0     0%   100%        1GB   100%  runtime.main
(pprof)
  • alloc_objects：分析应用程序的内存临时分配情况。
⋊> ~/testpprof go tool pprof -alloc_objects http://localhost:6060/debug/pprof/heap                                                                                                            
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/xxx/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz
Type: alloc_objects
Time: Aug 1, 2021 at 9:43pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
(pprof) top
Showing nodes accounting for 51, 100% of 51 total
      flat  flat%   sum%        cum   cum%
        41 80.39% 80.39%         41 80.39%  github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run (inline)
        10 19.61%   100%         10 19.61%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal
         0     0%   100%         41 80.39%  github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Live
         0     0%   100%         10 19.61%  github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Live
         0     0%   100%         51   100%  main.main
         0     0%   100%         51   100%  runtime.main
(pprof)

另外还有 inuse_objects 和 alloc_space 类别，分别对应查看每个函数所分别的对象数量和查看分配的内存空间大小，具体可根据情况选用。

8.5 排查频繁内存回收

你应该知道，频繁的 GC 对 golang 程序性能的影响也是非常严重的。虽然现在这个炸弹程序内存使用量并不高，但这会不会是频繁 GC 之后的假象呢？

为了获取程序运行过程中 GC 日志，我们需要先退出炸弹程序，再在重新启动前赋予一个环境变量，同时为了避免其他日志的干扰，使用 grep 筛选出 GC 日志查看：

GODEBUG=gctrace=1 ./go-pprof-practice | grep gc

日志输出如下：

可以看到，GC 差不多每 3 秒就发生一次，且每次 GC 都会从 16MB 清理到几乎 0MB，说明程序在不断的申请内存再释放，这是高性能 golang 程序所不允许的。

如果你希望进一步了解 golang 的 GC 日志可以查看《如何监控 golang 程序的垃圾回收》,为保证实验节奏，这里不做展开。

所以接下来使用 pprof 排查时，我们在乎的不是什么地方在占用大量内存，而是什么地方在不停地申请内存，这两者是有区别的。

由于内存的申请与释放频度是需要一段时间来统计的，所有我们保证炸弹程序已经运行了几分钟之后，再运行命令：

go tool pprof http://localhost:6060/debug/pprof/allocs

同样使用 top、list、web 大法：

image

image

可以看到 github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run 会进行无意义的内存申请，而这个函数又会被频繁调用，这才导致程序不停地进行 GC:

func (d *Dog) Run() {
    log.Println(d.Name(), "run")
    _ = make([]byte, 16 * constant.Mi)
}

这里有个小插曲，你可尝试一下将 16 * constant.Mi 修改成一个较小的值，重新编译运行，会发现并不会引起频繁 GC，原因是在 golang 里，对象是使用堆内存还是栈内存，由编译器进行逃逸分析并决定，如果对象不会逃逸，便可在使用栈内存，但总有意外，就是对象的尺寸过大时，便不得不使用堆内存。所以这里设置申请 16 MiB 的内存就是为了避免编译器直接在栈上分配，如果那样得话就不会涉及到 GC 了。

我们同样注释掉问题代码，重新编译执行，可以看到这一次，程序的 GC 频度要低很多，以至于短时间内都看不到 GC 日志了：

image

8.6 排查协程泄露

由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。

我们在浏览器里可以看到，此时程序的协程数已经多达 106 条：

image

虽然 106 条并不算多，但对于这样一个小程序来说，似乎还是不正常的。为求安心，我们再次是用 pprof 来排查一下：

go tool pprof http://localhost:6060/debug/pprof/goroutine

同样是 top、list、web 大法：

image

image

可能这次问题藏得比较隐晦，但仔细观察还是不难发现，问题在于 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink 在不停地创建没有实际作用的协程：

func (w *Wolf) Drink() {
    log.Println(w.Name(), "drink")
    for i := 0; i < 10; i++ {
        go func() {
            time.Sleep(30 * time.Second)
        }()
    }
}

可以看到，Drink 函数每次回释放 10 个协程出去，每个协程会睡眠 30 秒再退出，而 Drink 函数又会被反复调用，这才导致大量协程泄露，试想一下，如果释放出的协程会永久阻塞，那么泄露的协程数便会持续增加，内存的占用也会持续增加，那迟早是会被操作系统杀死的。

我们注释掉问题代码，重新编译运行可以看到，协程数已经降到 4 条了：

image

8.7 排查锁的争用

到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。

我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 4 条，但还显示有一个 mutex 存在争用问题。

相信到这里，你已经触类旁通了，无需多言，开整。

go tool pprof http://localhost:6060/debug/pprof/mutex

同样是 top、list、web 大法：

image

image

可以看出来这问题出在 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl。但要知道，在代码中使用锁是无可非议的，并不是所有的锁都会被标记有问题，我们看看这个有问题的锁那儿触雷了。

func (w *Wolf) Howl() {
    log.Println(w.Name(), "howl")

    m := &sync.Mutex{}
    m.Lock()
    go func() {
        time.Sleep(time.Second)
        m.Unlock()
    }()
    m.Lock()
}

可以看到，这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要，逻辑上说得通，并不一定真的是性能瓶颈，但既然它出现在我写的“炸弹”里，就肯定不是什么“业务需要”啦。

所以，我们注释掉这段问题代码，重新编译执行，继续。

8.8 排查阻塞操作

好了，我们开始排查最后一个问题。

在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。

image

可以看到，这里仍有 2 个阻塞操作，虽然不一定是有问题的，但我们保证程序性能，我们还是要老老实实排查确认一下才对。

go tool pprof http://localhost:6060/debug/pprof/block

top、list、web，你懂得。

image

image

可以看到，阻塞操作位于 github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee：

func (c *Cat) Pee() {
    log.Println(c.Name(), "pee")

    <-time.After(time.Second)
}

你应该可以看懂，不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。

这里有个疑点，就是上文中是可以看到有两个阻塞操作的，但这里只排查出了一个，我没有找到其准确原因，但怀疑另一个阻塞操作是程序监听端口提供 porof 查询时，涉及到 IO 操作发生了阻塞，即阻塞在对 HTTP 端口的监听上，但我没有进一步考证。

不管怎样，恭喜你完整地完成了这个实验。

9 代码优化建议

以下是一些从其它项目借鉴或者自己总结的实践经验，它们只是建议，而不是准则，实际项目中应该以性能分析数据来作为优化的参考，避免过早优化。

  1. 对频繁分配的小对象，使用 sync.Pool 对象池避免分配
  2. 自动化的 DeepCopy 是非常耗时的，其中涉及到反射，内存分配，容器(如 map)扩展等，大概比手动拷贝慢一个数量级
  3. 用 atomic.Load/StoreXXX，atomic.Value, sync.Map 等代替 Mutex。(优先级递减)
  4. 使用高效的第三方库，如用fasthttp替代 net/http
  5. 在开发环境加上-race编译选项进行竞态检查
  6. 在开发环境开启 net/http/pprof，方便实时 pprof
  7. 将所有外部IO(网络IO，磁盘IO)做成异步

参考

一看就懂系列之Golang的pprof

煎鱼-Go 大杀器之性能剖析 PProf（上）

Go应用性能剖析

[WOLFOGRE’S BLOG]golang pprof 实战

码农桃花源-深度解密Go语言之pprof

文章作者: wish
文章链接: https://debug-lixiwen.github.io/2021/07/18/shi-zhan/
版权声明: 本博客所有文章除特別声明外，均采用 CC BY 4.0 许可协议。转载请注明来源 wish !
无标签
赏
评论
评论
  目录