go基础工具-pprof

237 阅读3分钟

概述

在一个庞大的程序中,有时候出现一些诡异的卡顿或者内存飙升,这时候光靠经验和认知去定位性能不佳的代码往往都不靠谱。这时候就需要用到pprof工具了。

在golang官方提供的性能测试工具中,分别提供了net/http/pprof和runtime/pprof两个包,两个包的使用场景分别如下:

runtime/pprof: 作用于一次性运行的代码块,如脚本程序等。
net/http/pprof: 是runtime/pprof的二次封装,主要作用于不可结束的代码块,如web应用。

pprof作用原理:

pprof是以profile.proto读取分析样本的集合,并生成文本和图形化报告输出。
profile.proto是一个 Protocol Buffer v3 的描述文件,描述了一组callstack和symbolization信息,作用是表示统计分析的一组采样的调用栈,是很常见的stacktrace配置文件格式。

支持输出格式:

  • 生成报告
  • 交互式终端输出
  • web界面输出

Profiling类型:

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

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

Block Profiling: 阻塞分析,记录goroutine阻塞等待同步(包括定时器通道)的位置

Mutex Profiling: 互斥锁分析,报告互斥锁的竞争情况

runtime/pprof

package main

import (
    "os"
    "runtime/pprof"
    "sync"
)

func addData() {
    data := make([]int, 0)
    c := 0
    for i := 0; i < 100000; i++ {
        c = i + c
        data = append(data, c)
    }
}

func workOnce(wg *sync.WaitGroup) {
    addData()
    wg.Done()
}

func main() {
    cpuf, err := os.OpenFile("cpu.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
    if err != nil {
        panic(err)
    }
    pprof.StartCPUProfile(cpuf)
    defer cpuf.Close()
    defer pprof.StopCPUProfile()
    var wg sync.WaitGroup
    wg.Add(100)
    for i := 0; i < 100; i++ {
        go workOnce(&wg)
    }
    wg.Wait()
    memf, err := os.OpenFile("mem.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
    if err != nil {
        panic(err)
    }
    pprof.WriteHeapProfile(memf)
    memf.Close()
}

编译通过后执行下面命令获得cpu使用情况

go tool pprof cpu.pprof
/***
得到结果
Type: cpu
Time: Mar 22, 2021 at 4:58pm (CST)
Duration: 201.01ms, Total samples = 230ms (114.42%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
***/

使用top指令

(pprof) top
Showing nodes accounting for 230ms, 100% of 230ms total
Showing top 10 nodes out of 44
      flat  flat%   sum%        cum   cum%
     100ms 43.48% 43.48%      100ms 43.48%  runtime.memmove
      40ms 17.39% 60.87%       40ms 17.39%  runtime.memclrNoHeapPointers
      30ms 13.04% 73.91%       30ms 13.04%  runtime.osyield
      30ms 13.04% 86.96%       30ms 13.04%  runtime.stdcall2
      20ms  8.70% 95.65%      170ms 73.91%  main.addData
      10ms  4.35%   100%       10ms  4.35%  runtime.(*pallocBits).summarize
         0     0%   100%      170ms 73.91%  main.workOnce
         0     0%   100%       10ms  4.35%  runtime.(*mcache).prepareForSweep
         0     0%   100%       10ms  4.35%  runtime.(*mcache).releaseAll
         0     0%   100%       10ms  4.35%  runtime.(*mcentral).uncacheSpan

Duration:程序执行时间。在本例中golang自动分配任务给多个核执行程序,总计耗时201.01ms,采样时间为230ms;也就是说假设有10核执行程序,平均每个核的采样23ms的数据。

(pprof) :命令行提示。表示当前在go tool的pprof工具命令行中,go tool还包括cgo、doc、pprof、test2json、trace等多种命令。

top:pprof的指令之一,显示pprof文件中的前10项数据,可以通过top 20等方式显示20行数据;当然pprof下有很多指令,例如list、pdf、eog等等。

flat/flat% :分别表示在当前层级cpu的占用时间和百分比。例如runtime.memmove在当前层级占用cpu时间100ms,占比本次采集时间的43.48%。

cum/cum% :分别表示截止到当前层级累计的cpu时间和占比。例如main.addData累计占用时间170ms,占本次采集时间的73.91%。

sum% :所有层级的cpu时间积累占用,从小到大一直积累到100%,即230ms。

(pprof) list main.addData
Total: 230ms
ROUTINE ======================== main.addData in D:\zone\project\iot\test\main.go
                                                                                       .          .      9:func addData() {
         .          .     10:   data := make([]int, 0)
         .          .     11:   c := 0
         .          .     12:   for i := 0; i < 100000; i++ {
         .          .     13:           c = i + c
      20ms      170ms     14:           data = append(data, c)
         .          .     15:   }
         .          .     16:}
         .          .     17:
         .          .     18:func workOnce(wg *sync.WaitGroup) {
         .          .     19:   addData()

使用pprof的list指令,可以看到程序的14行占用了170ms,由此可以确定优化的方向。分析该行代码,可知slice的初始容量为0,导致循环中append时将发生多次扩容(slice的扩容方式说明:当容量不超过1024时,扩容为原来的2倍,超出则扩容为1.25倍)。

(pprof) web
failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in %PATH%

如果想使用web输出,在未安装相关插件的情况下,会得到上面的提示。

进入官网:graphviz.org/download/

下载对应版本安装后加入环境变量path即可

net/http/pprof

package main

import (
    "net/http"
    "time"

    _ "net/http/pprof"
)

func addData() {
    data := make([]int, 100000)
    c := 1
    for i := 0; i < 100000; i++ {
        c = i + c
        data[i] = c
    }
}

func work() {
    for ; ; time.Sleep(1 * time.Second) {
        go addData()
    }
}

func httpWork(w http.ResponseWriter, r *http.Request) {
    addData()
}

func main() {
    go work()
    http.HandleFunc("/work", httpWork)
    http.ListenAndServe(":8080", nil)
}

运行后打开http://localhost:8080/debug/pprof/

可以看到当前服务的运行情况

也可以使用下面的命令查看内存情况

go tool pprof main.exe http://localhost:8080/debug/pprof/heap

火焰图

安装

go get -v github.com/uber/go-torch
git clone http://github.com/brendangregg/FlameGraph.git
git clone http://github.com/adjust/go-wrk.git

FlameGraph是画图需要的工具,而wrk是模拟并发访问的工具。

将FlameGraph所在路径添加到环境变量中。

注意:windows下需要运行FlameGraph需要安装:perl
网址:
https://www.activestate.com/products/perl/ (慢)
https://strawberryperl.com/ (快)
windows下未必能成功使用,可使用(注1)方法查看

使用go-wrk命令模拟并发操作

4个线程|每个线程100个请求|共100000次请求

go-wrk -t=4 -c=100 -n=100000 http://localhost:8080/work

同时开启go-torch工具对http://localhost:8080采集30s信息,采集完毕后会生成svg文件,用浏览器打开就是火焰图。

go-torch -u http://localhost:8080 -t 30

亦可以直接使用生成的信息 (注1)

go tool pprof main -http=:6666 http://localhost:8080/debug/pprof/profile //生成信息打开网页查看

go tool pprof main http://localhost:8080/debug/pprof/heap //采集内存信息
go tool pprof main http://localhost:8080/debug/pprof/profile //采集cpu信息

trace

trace和pprof一样,也是go tool下的工具。

package main

import (
    "os"
    "runtime/trace"
    "sync"
)

func addData() {
    data := make([]int, 0)
    c := 0
    for i := 0; i < 100000; i++ {
        c = i + c
        data = append(data, c)
    }
}

func workOnce(wg *sync.WaitGroup) {
    addData()
    wg.Done()
}

func main() {
    tracef, err := os.OpenFile("trace.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
    if err != nil {
        panic(err)
    }
    trace.Start(tracef)
    defer tracef.Close()
    defer trace.Stop()
    var wg sync.WaitGroup
    wg.Add(100)
    for i := 0; i < 100; i++ {
        go workOnce(&wg)
    }
    wg.Wait()
}

编译执行

调用命令查看程序的执行情况

go tool trace -http=127.0.0.1:8080 trace.pprof