Golang profile 用法

ag9920
1,039 阅读7分钟

一起养成写作习惯！这是我参与「掘金日新计划 · 4 月更文挑战」的第16天，点击查看活动详情。

开篇

作为 Golang 开发者，了解程序的性能和瓶颈很有必要。简单的API调用，背后的性能消耗也可能是巨大的。好在 Golang 提供了原生的支持，pprof 工具方便我们对线上请求的处理过程有更深入的了解。尤其是在排查问题时更是一把利器。

根据笔者个人经验，此前线上出现过因为SQL语句参数不对，导致从 MySQL 查询了巨量数据，导致实例 OOM，也有过 local cache 姿势不对，导致内存飙升。其实如果开了 pprof，都能够很快帮你发现问题。日常开发中，多跑跑benchmark 和 profile，会帮助你对代码的性能有更深的理解。

在 medium 上看到一句话感觉说的非常对：

Optimizing your code based on assumptions is not a best practice of course. You need to have insights about your code performance and bottlenecks to be able to optimize it efficiently.

不要基于假设来优化代码，你需要对代码性能和瓶颈有足够的洞察，才能够去有效地优化。

Profile

Go 提供了以下几个指标：

  • Goroutine：所有当前 Goroutine 的堆栈跟踪
  • CPU：runtime 返回的 CPU 堆栈跟踪
  • Heap：当前存活对象的内存分配采样
  • Allocation：所有此前内存分配的样本
  • Thread：导致创建新操作系统线程的堆栈跟踪
  • Block：导致同步原语阻塞的堆栈跟踪
  • Mutex：竞争互斥锁持有者的堆栈跟踪

如何生成 Profile

go test

此前的一篇文章我们有提到 解析 Golang 测试 - 原生支持（1）。使用 go test -bench=. 会执行当前包下所有的 benchmark。

testing 包同样对于 profiling 提供了支持，使用下面的命令就可以执行所有的 benchmark 并且输出 CPU 以及 memory 的 profile 数据：

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

http 支持实时 profile

官方提供的 net/http/pprof 包提供了支持，你只需要 import 进来即可，不需要实际调用。

import _ "net/http/pprof"

原因很简单，我们只是需要pprof 包的init() 函数被调用即可：

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

它会注册对应的 handler 到 DefaultServeMux（ net/http/server.go 提供的默认的 server）


// NewServeMux allocates and returns a new ServeMux.
func NewServeMux() *ServeMux { return new(ServeMux) }

// DefaultServeMux is the default ServeMux used by Serve.
var DefaultServeMux = &defaultServeMux

var defaultServeMux ServeMux

在 net/http/pprof 的 init() 函数中注册的 handler，比如 Index，会将 profile 写入 http.ResponseWriter。

所以，用起来就非常简单了，你只需要第一步 import 进来 net/http/pprof，第二步启动默认的 http server 即可。

package main

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

func doSomething() {
        // ...
}

func main() {
        go doSomething()
        http.ListenAndServe("0.0.0.0:6060", nil)
}

当然，如果你已经有一个依赖 DefaultServeMux 的 server 启动了，就不需要这一段代码了，只需要import pprof 包初始化即可。启动后，你就可以通过 http://localhost:6060/debug/pprof/ 来查看所有的 profile了。

image.png

当然，你也可以单独看某一项指标，如下：

  • 访问这个链接会得到一个内存 Profiling 结果的文件。内存显示默认的Type是 inuse_space，即常驻内存。与之对应的是 alloc_objects，表示临时分配的内存。
go tool pprof http://localhost:6060/debug/pprof/heap
  • 访问这个链接会自动进行 CPU profiling，持续 30s，并生成一个文件供下载
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30
  • goroutine 阻塞的 profile（需要在代码里显式调用 runtime.SetBlockProfileRate)
go tool pprof http://localhost:6060/debug/pprof/block
  • 竞争锁的 profile （需要在代码里显式调用 runtime.SetMutexProfileFraction)
go tool pprof http://localhost:6060/debug/pprof/mutex
  • 查看各个goroutine执行耗时情况，持续5s，包括网络等待耗时、同步耗时、GC耗时等。
go tool pprof http://localhost:6060/debug/pprof/trace?seconds=5

代码中手动处理

pprof 底层依赖的 runtime/pprof 其实提供了相关的方法。你可以通过 pprof.StartCPUProfile(io.Writer) 以及 pprof.StopCPUProfile() 启动和关闭 CPU Profile。相关 profile 的数据将会写到 io.Writer 里。

更简单的方式是用开源的 github.com/pkg/profile 提供的包装：

go get github.com/pkg/profile

然后直接在 defer 里这样用即可：

func main() {
	defer profile.Start(profile.ProfilePath(".")).Stop()
	// execute logic
}

profile.ProfilePath(".") 代表着在当前目录下生成 profile 文件，默认是 cpu.pprof，你可以通过 options 来进行调整。最后调用 profile.Start() 即可.

// CPUProfile enables cpu profiling. Note: Default is CPU
defer profile.Start(profile.CPUProfile).Stop()

// GoroutineProfile enables goroutine profiling.
// It returns all Goroutines alive when defer occurs.
defer profile.Start(profile.GoroutineProfile).Stop()

// BlockProfile enables block (contention) profiling.
defer profile.Start(profile.BlockProfile).Stop()

// ThreadcreationProfile enables thread creation profiling.
defer profile.Start(profile.ThreadcreationProfile).Stop()

// MemProfileHeap changes which type of memory profiling to 
// profile the heap.
defer profile.Start(profile.MemProfileHeap).Stop()

// MemProfileAllocs changes which type of memory to profile 
// allocations.
defer profile.Start(profile.MemProfileAllocs).Stop()

// MutexProfile enables mutex profiling.
defer profile.Start(profile.MutexProfile).Stop()

解读 Profile

这个其实是重点，进 production 的服务，坦率地讲都会有公司基建提供的 pprof 能力，不太需要个人来启动上一步的 http server 收集 profile。

但有，不代表能看懂。根据笔者日常工作经验看，很多时候 pprof 给出的各项指标的含义，如何解读，还是个不小的门槛。不熟悉的小伙伴经常会意识流，大概去猜一些指标，或者现查。

这里我建议大家一次性看懂，记熟相关的概念，一定会在线上出问题的时候帮你省下大量的排查时间。

pprof 是一个可视化分析 profile 数据的工具，查看 pprof 可以通过 go tool pprof 命令，如果你嫌麻烦也可以直接安装 pprof。

如果对 pprof 命令希望充分了解，可以直接到命令行输入 go tool pprof 回车，你就会看到支持的 option 以及格式。这里我们讲几个典型case，应该能覆盖很多场景。

go tool pprof

go tool pprof <format> [options] [binary] <source> ...

我们忽略 format，格式意义不大，记住以下几点就ok：

  • source 参数代表生成的分析数据来源，可以是本地文件，也可以是http地址。
  • 添加 -http=:{port} 选项会在指定的 port 上启动一个server，你可以在可以交互的 web 页面上自由地浏览可视化的 profile 数据，例如 go tool pprof -http=":8081" cpu.prof

image.png

  • 不添加 -http 选项，直接提供 source 的话，将会进入命令行交互模式，你可以输入指令，查看 profile 信息。go tool pprof cpu.prof image.png

注：上面两个例子中 source 参数的值 cpu.prof 即为我们从上一节获取的二进制 profile 文件。

更多情况下我们会直接用 http server 的 URL 作为 source 参数。如

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

这里其实不加后缀的话，go tool pprof 也会自动添加上 /debug/pprof/profile 这部分，默认采样的是 CPU。上面这个命令等同于：go tool pprof http://127.0.0.1:6060

交互模式下有三个很好用的命令：

  • top：列出来性能消耗最大的前 N 个函数； image.png
  • web：生成 svg 图片，根据箭头，函数狂大小，就能判断出哪个函数耗时/占用内存最高；
  • list {函数名}，查看问题具体在代码中的位置。

image.png

一个典型的 top 结果如下，虽然各个profile单位和语义不同，结果都是一样的格式，这里我们过一下：

image.png

可以看到，最后一列是函数的名称

  • flat: 该函数占用 CPU 的耗时（或内存占用）；
  • flat%: 该函数占用 CPU 的耗时百分比（或内存占用百分比）；
  • sum%: top命令中排在它上面的函数以及本函数 flat% 之和；
  • cum: 当前函数加上该函数调用之前的累计CPU耗时（或内存占用）；
  • cum%: 当前函数加上该函数调用之前的累计CPU耗时百分比（或内存占用百分比）；

在内存 heap 的 profile 中

  • -inuse_space：分析应用程序的常驻内存占用情况
  • -alloc_objects：分析应用程序的内存临时分配情况

参考资料

官方博客 Profiling Go Programs

How I profiled Go code with pprof

profile like a master

Golang之pprof使用

avatar
文章
阅读
粉丝