golang的pprof与火焰图实战-每日运维

golang的pprof与火焰图实战
1 前言

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

blog.wolfogre.com/posts/go-pp…

www.liwenzhou.com/posts/Go/pe…

blog.wolfogre.com/posts/go-pp…

github.com/wolfogre/bl…

golang2.eddycjy.com/posts/ch6/0…

github.com/eddycjy/blo…

github.com/brendangreg…

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

www.cnblogs.com/jiujuan/p/1…

1.1 性能分析

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

–维基百科

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

1.2 代码开发上线步骤

上线前

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

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

上线后

线上突然大量报警，接口超时，错误数增加

终极解决方案：看日志、看监控；使用性能分析工具分析程序的性能，找到瓶颈

临时解决方案：首先要降级、限流、回滚，先止损

总结

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

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

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

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

一般常规分析内容：

cpu：程序对cpu的使用情况 - 使用时长，占比等

内存：程序对cpu的使用情况 - 使用时长，占比，内存泄露等。如果在往里分，程序堆、栈使用情况

I/O：IO的使用情况 - 哪个程序IO占用时间比较长

golang 程序中分析内容：

goroutine：go的协程使用情况，调用链的情况

goroutine leak：goroutine泄露检查

go dead lock：死锁的检测分析

data race detector：数据竞争分析，其实也与死锁分析有关

1.3 golang 性能调试优化方法

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

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

golang 性能调试优化方法：

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

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

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

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

它的最原始程序是 gperftools - github.com/gperftools/… 的 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指标采样的维度

CPU（profile）

CPU Profiling：CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置。

报告CPU的使用情况，定位到热点（消耗CPU周期最多的）代码。默认情况下Go以100HZ的频率进行CPU采样

Goroutine

Goroutine Profiling： Goroutine 分析，可以对当前应用程序正在运行的 Goroutine 进行堆栈跟踪和分析。这项功能在实际排查中会经常用到，因为很多问题出现时的表象就是 Goroutine 暴增，而这时候我们要做的事情之一就是查看应用程序中的 Goroutine 正在做什么事情，因为什么阻塞了，然后再进行下一步。

系统线程

获取导致创建 OS 线程的 goroutine 堆栈

堆内存/内存剖析（heap）

Memory Profiling：内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏。

包含每个 goroutine 分配大小，分配堆栈等。

每分配 runtime.MemProfileRate(默认为512K) 个字节进行一次数据采样。

内存剖析（allocs）：报告所有内存分配历史

阻塞操作

Block Profiling：阻塞分析，记录 Goroutine 阻塞等待同步（包括定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置。

获取导致阻塞的 goroutine 堆栈(如 channel, mutex 等)，使用前需要先调用 runtime.SetBlockProfileRate

锁竞争

Mutex Profiling：互斥锁分析，报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置。

执行追踪（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，代码如下：


    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:%vn", 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 排查时，我们在乎的不是什么地方在占用大量内存，而是什么地方在不停地申请内存，这两者是有区别的。

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 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。
    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/
8.3 排查 CPU 占用过高
我们首先通过活动监视器（或任务管理器、top 命令，取决于你的操作系统和你的喜好），查看一下炸弹程序的 CPU 占用：


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



很明显，CPU 占用过高是 github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat 造成的。
可以看到，是第 24 行那个一百亿次空循环占用了大量 CPU 时间，至此，问题定位成功！

接下来有一个扩展操作：图形化显示调用栈信息，这很酷，但是需要你事先在机器上安装 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 占用率已经下来了，但是内存的占用率仍然很高：


可以看到这次出问题的地方在 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 大法：


可以看到 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 日志了：

8.6 排查协程泄露
由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。
我们在浏览器里可以看到，此时程序的协程数已经多达 106 条：

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

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

同样是 top、list、web 大法：


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

8.7 排查锁的争用
到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。
我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 4 条，但还显示有一个 mutex 存在争用问题。
相信到这里，你已经触类旁通了，无需多言，开整。

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

同样是 top、list、web 大法：


可以看出来这问题出在 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 排查阻塞操作
好了，我们开始排查最后一个问题。
在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。

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

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

top、list、web，你懂得。


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


    func (c *Cat) Pee() {

        log.Println(c.Name(), "pee")

golang的pprof与火焰图实战

1.1 性能分析

1.2 代码开发上线步骤

1.3 golang 性能调试优化方法

3.1 pprof指标采样的维度

3.2 原理

3.2.1 CPU采样

3.2.2 Goroutine & ThreadCreate采样

3.2.3 Heap（堆内存）采样

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

5.1 go test

5.2 runtime/pprof

5.2.1 采集CPU(CPU 占用过高)

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

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

5.2.4 采集goroutine(协程泄露)

5.2.5 采集mutex(锁的争用)

5.2.6 采集block(阻塞操作)

8.1.2 套路2-推荐

8.2 背景说明

8.3 排查 CPU 占用过高

8.4 排查内存占用过高

8.5 排查频繁内存回收

8.6 排查协程泄露

8.7 排查锁的争用

8.8 排查阻塞操作

相关文章

发布评论取消回复

法医

百度搜索：蓝易云 – JDK1.8在LINUX下安装教程

万字长文 | MatrixOne 的 MySQL 协议实现

一个简单小工具obtool，助你成为Oceanbase高级专家

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

golang的pprof与火焰图实战

1.1 性能分析

1.2 代码开发上线步骤

1.3 golang 性能调试优化方法

3.1 pprof指标采样的维度

3.2 原理

3.2.1 CPU采样

3.2.2 Goroutine & ThreadCreate采样

3.2.3 Heap（堆内存）采样

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

5.1 go test

5.2 runtime/pprof

5.2.1 采集CPU(CPU 占用过高)

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

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

5.2.4 采集goroutine(协程泄露)

5.2.5 采集mutex(锁的争用)

5.2.6 采集block(阻塞操作)

8.1.2 套路2-推荐

8.2 背景说明

8.3 排查 CPU 占用过高

8.4 排查内存占用过高

8.5 排查频繁内存回收

8.6 排查协程泄露

8.7 排查锁的争用

8.8 排查阻塞操作

相关文章

发布评论 取消回复

法医

百度搜索：蓝易云 – JDK1.8在LINUX下安装教程

万字长文 | MatrixOne 的 MySQL 协议实现

一个简单小工具obtool，助你成为Oceanbase高级专家

发布评论取消回复