关于golang:golang性能分析利器pprof

作为一名 gopher, 不晓得你是否遇到过以下问题？

CPU 忽然飙高(甚至死循环,CPU 跑满)？
某个性能接口 QPS 在压测中始终压不下来？
利用呈现 goroutine 泄露？
内存居高不下？
在某处加锁的逻辑中，迟迟得不到锁？

你是否能得心应手的找到问题的症结所在，你又是应用什么办法或工具解决的呢？明天我将介绍下我常常应用的工具 pprof. 它是 golang 自带的性能剖析大杀器，基本上能疾速解决上述问题。

应用 pprof 有三种姿态，一种是应用 runtime/pprof/pprof.go 另一种是应用 net/http/pprof/pprof.go（底层也是应用runtime/pprof）, 还有一种是在单元测试中生成 profile 数据。具体的办法在对应的pprof.go 文件结尾有阐明。

package main

import (
    "flag"
    "log"
    "os"
    "runtime"
    "runtime/pprof"
)

var cpuprofile = flag.String("cpuprofile", "","write cpu profile to `file`")
var memprofile = flag.String("memprofile", "","write memory 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() // error handling omitted for example
        if err := pprof.StartCPUProfile(f); err != nil {log.Fatal("could not start CPU profile:", err)
        }
        defer pprof.StopCPUProfile()}

    // ... rest of the program ...

    if *memprofile != "" {f, err := os.Create(*memprofile)
        if err != nil {log.Fatal("could not create memory profile:", err)
        }
        defer f.Close() // error handling omitted for example
        runtime.GC()    // get up-to-date statistics
        if err := pprof.WriteHeapProfile(f); err != nil {log.Fatal("could not write memory profile:", err)
        }
    }
}

这种形式须要你手动启动须要 pprof 的类型，比方，开启 CPU profile 还是 heap profile 等等，pprof 会在利用启动到完结的整个生命周期生成 profile 文件。其实生成 profile 数据是会损耗性能的，生产环境不倡议始终开启，能够在须要剖析的时候长期采集那个时刻的数据，如通过监听系统信号的形式开启 / 敞开 pprof, 示例代码如下：

package main

import (
    "flag"
    "log"
    "os"
    "runtime"
    "runtime/pprof"
)
var cpuprofile = flag.String("cpuprofile", "","write cpu profile to `file`")
var memprofile = flag.String("memprofile", "","write memory profile to `file`")

func signalStopPprof(f *os.File) {c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGUSR2)
    for _ = range c {pprof.StopCPUProfile()
        log.Println("stop  profile")
        _ = f.Close()}
}
func signalStartPprof(f *os.File) {c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGUSR1)
    for _ = range c {_ = f.Truncate(0)
        if err := pprof.StartCPUProfile(f); err != nil {log.Println("could not start CPU profile:", err)
        }
    }
}
func main() {flag.Parse()
    if *cpuprofile != "" {f, err := os.Create(*cpuprofile)
        if err != nil {log.Fatal("could not create CPU profile:", err)
        }
        go func() {signalStartPprof(f)
        }()
        go func() {signalStopPprof(f)
        }()}
    // ... rest of the program ...
}

不过自己还是更加喜爱第二种形式net/http/pprof

package main

import (
    "log"
    "net/http"
    _ "net/http/pprof"
)

func main() {go func() {log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
  // ... rest of the program ...
}

是不是很简略，这种形式只须要开启 http 服务，并且import _ "net/http/pprof", 他会主动把相应的 http 的 handleFunc 注册下来，若你应用的不是DefaultServeMux, 须要本人手动注册下。

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

go test -cpuprofile cpu.prof -memprofile mem.prof -bench .

在上文如何应用 pprof 中介绍的三种开启 pprof 的形式，他们都会生成 profile 二进制文件，有三种形式能够剖析这个二进制文件

姿态一：通过交互命令行, 办法：go tool pprof {profile 文件}

若是通过 http 形式开启 pprof，能够

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30

若是通过形式 1 和 3 生成文件, 能够

go tool pprof cpu.prof

命令交互行如下
姿态二：通过 web 形式查看，办法 go tool pprof -http=:6060 {profile 文件}

而后就能够在浏览器中拜访 http://localhost:6060/

当然也有一种形式在姿态一中介绍的命令行交互中输出 web 会生成 .svg 文件，不过须要装置 graphviz 来关上这个文件，不举荐，还是倡议应用命令行或本地启动 web 服务来查看 profile 数据.

本人写了一个模拟程序，模仿 CPU 问题，

依照上述姿态一关上命令行交互，执行top10, 输入采样期间 CPU 应用最高的 10 个办法

这里简略介绍下 flat flat% sum% cum cum% 这五个参数的含意, 具体能够查看 Pprof and golang – how to interpret a results?

flat：指的是该办法所占用的 CPU 工夫（不蕴含这个办法中调用其余办法所占用的工夫）

flat%: 指的是该办法 flat 工夫占全副采样工夫的比例

cum：指的是该办法以及办法中调用其余办法所占用的 CPU 工夫总和，这里留神区别于 flat

cum%: 指的是该办法 cum 工夫占全副采样工夫的比例

sum%: 指的是执行到以后办法累积占用的 CPU 工夫总和，也即是后面 flat% 总和

上图能够看出 worker()占用 CPU 工夫较久，咱们能够 list main.worker 查看具体代码

当然也能够通过上述姿态二，启动 web 服务查看火焰图go tool pprof -http=:6061 cpu.profile

关上 http://localhost:6061/ui/ 火焰图如下，其中色彩越红代表占用的 CPU 工夫越多

找到了耗时比拟久的中央，就能看看失常的业务代码还是能够优化的逻辑，就能够优化后在 pprof

排查内存再用过高问题

其中 inuse_space 示意查看常驻内存的应用状况

list 查看相应的函数

原来是统一在 append 内存，并持有到 1GB 不开释

当然还能够应用alloc_objects：剖析应用程序的内存长期分配情况

能够看到利用稳固后，除了下面初始调配 1GB 外，利用长期内存调配次要在 worker 中

例如 goroutine 泄露等问题，办法如下

能够打出各个 goroutine 的调用栈

能够看到有 900+ 的 goroutine 阻塞在 runtime/gopark 并且是由 main.goroutine.fun1 办法引起的 list 查看办法内容list main.goroutine.fun1

能够看出次要是阻塞在 channel c 上. 当然也能够通过 traces runtime.gopark 查看那些办法最终阻塞在 gopark 上，另外也能够在 web 页面 http://localhost:6060/debug/p… 间接查看。

锁的问题可能导致程序运行迟缓，pprof mutex 相干的须要设置采样率

runtime.SetMutexProfileFraction(1), 若采样率 <0 将不进行采样

能够看出，次要在 main.mutex.func1 上，能够查看调用链

list main.mutex.func1

能够看出次要阻塞在锁 m 上

区别于 4，这里次要是记录 goroutine 阻塞期待同步的地位, 而 4 中次要是互斥锁剖析，报告互斥锁的竞争状况。同样须要设置采样率runtime.SetBlockProfileRate(1)

次要主色在 chanrecv1 上，查看源码

能够发现次要阻塞在 channel c 上

下面曾经一步一步演示了一遍常见利用性能问题，以及如何剖析定位，前面将写下这些剖析数据背地是如何采集，原理是什么。

最初附上本次测试源码 https://github.com/John520/pp…

pprof 官网 README
Profiling Go Programs
Golang 大杀器之性能分析 PProf
golang pprof 实战
https://golang2.eddycjy.com/p…

关于golang:golang性能分析利器pprof

前言

如何应用 pprof

1. runtime/pprof 形式 pprof

2. net/http/pprof 形式 pprof

3. 单元测试中进行 profile

剖析 pprof

实战演练

1. 定位 CPU 问题

2. 定位内存问题

3. 定位 goroutine 问题

4. 定位锁问题

5. 定位 goroutine 阻塞期待同步问题

写在最初

参考文献