Go pprof使用初探（配合小实验）

zfx001
99 阅读4分钟

1 pprof是什么？

pprof是一个对go程序的性能分析工具，分析go程序的运行情况，包括对CPU、内存、锁等资源的使用情况。

2 如何使用？

2.1 启动pprof

常用的方式是通过http请求去获取pprof采集的数据，做法为在程序中启动一个http服务并且引入net/http/pprof包，之后便可通过浏览器进行访问。

package main

import _ "net/http/pprof"

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

可以看到pprof包中的init函数中注册了对应路由的处理函数，可以通过这些pprof提供的方法来对程序进行分析。

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

下面是一个总的分析首页页面，指标下面有各指标的含义。点进去看的可读性很差，所以接下来的小结会通过其他方式具体的分析指标。

2.2 各指标分析

通过浏览器的方式查看对应指标（黄色字体可替换为不同的指标）的各种视图

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

通过命令行的方式查看对应指标的情况

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

下文以以上两种方式来进行分析以下BugDemo项目的性能问题，本文也参考了博客blog.wolfogre.com/posts/go-pp…

https://github.com/wolfogre/go-pprof-practice

启动后可以看到CPU占比以及内存占比都比较高。

profile

CPU指标

执行以下命令，会对程序进行30的分析（此时间可以自己设置seconds参数），之后便会进入命令行交互模式。

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

可以看到输出的几个关键信息：

  1. 分析的是哪个程序
  2. 分析的指标是CPU的数据
  3. 分析的持续时间是30秒，采样时间是19.96秒（这两个数据的具体对应关系还需确认）

执行top命令，就可以看到对应资源的消耗情况

  • flat：函数自身的运行耗时。
  • flat%：函数自身在 CPU 运行耗时总比例。
  • sum%：函数自身累积使用 CPU 总比例。
  • cum：函数自身及其调用函数的运行总耗时。
  • cum%：函数自身及其调用函数的运行耗时总比例。
  • 最后一列为对应函数名

思考两个问题，什么情况下flat==cum?和flat==0?，一是没有调用其他的函数情况下，二是只有调用其他函数的情况下。

通过top命令可以看出，资源消耗最大的是Eat函数，之后通过list命令查看对应的代码，可以看到是一个超大for循环空转导致的，注释掉代码后，便可以解决。

最后，通过web命令可直观的看出具体的调用关系及调用时间。

排查及解决后的结果：

heap

堆内存使用指标

还是和CPU排查的流程一样，使用top、list、web来排查解决问题，但此时可以看到，采样的类型为inuse_space，那是否还有其他采样类型呢？

为了更直观，我们使用浏览器的方式来查看采样数据，可以看到除了inuse_space以外还有三个指标。

  1. alloc_objects:程序累计申请的对象数
  2. alloc_space:程序累计申请的内存大小
  3. inuse_objects:程序当前持有的对象数
  4. inuse_space:程序当前占用的内存大小

alloc_objects:

日志的正常输出，属于正常现象。

alloc_space：

可以看到Run这个方法，虽然一次申请的内存很小，但它却一直在不断的申请，所有我们把它注释掉。而Pee这个方法在30秒后开始1M的申请内存，申请到1G，也是把它注释掉。

inuse_objects和inuse_space

可以看到都是Pee这个方法累计申请内存导致的，上面我们已经解决

goroutine

通过火焰图可以看到Drink函数调用时间很长，由此可定位并解决。

mutex

同样，通过上面的方法定位锁的竞争情况，本代码中主要是等待锁释放的时间较长。

block

同样，通过上面的方法定位阻塞的问题，本代码中主要是读取一个channel，需要耗时一秒。

可以看到，在解决上面的问题后，block指标还有一个问题，点进去可以看到是与httpserver相关与业务逻辑无关，至此排查完成。

avatar
文章
阅读
粉丝