• 性能分析，有哪些工具可以用？
  • 概要文件的采样、收集和输出是怎样的，包括怎样启动和停止采样、怎样设定采样频率以及怎样控制输出内容的格式和详细程度？
  • 每一种概要信息代表了什么，包含什么样的内容？
  • runtime/pprof.Lookup 函数的正确调用方式是什么？
  • 通过这些怎么检查程序瓶颈？
  • 怎么为基于 HTTP 协议的网络服务添加性能分析接口？
  • runtime/trace 代码包的功用是什么?
专栏：48 & 49 | 程序性能分析基础

— Kelly Sikkema

Go 程序性能分析基础

接口和工具

API

Go 语言为程序开发者们提供了丰富的性能分析 API 以及非常好用的标准工具。这些 API 主要存在于一下三个代码包中：

  • runtime/pprof
  • net/http/pprof (常用)
  • runtime/trace (还没接触)

另外，runtime 代码包中还包含了一些更底层的 API。它们可以被用来收集或输出 Go 程序运行过程中的一些关键指标，并帮助我们生成相应的概要文件以供后续分析使用。

Tools

标准工具主要有：

  • go tool pprof(常用)
  • go tool trace(还没接触)

它们可以解析概要文件中的信息，并以人类易读的方式把这些信息展示出来。

此外，go test 命令也可以在程序测试完成后生成概要文件。

概要文件

在 Go 语言中，用于分析程序性能的概要文件有三种：CPU 概要文件(CPU Profile)、内存概要文件(Mem Profile) 和阻塞概要文件(Block Profile)

这些概要文件中包含的是：在某一段时间内，对 Go 程序的相关指标进行多次采样后得到的概要信息。

  • 对 CPU 概要文件来说，其中的每一段独立的概要信息都记录着，在进行某一次采样的那个时刻，CPU 上正在执行的 Go 代码。

  • 对 内存概要文件来说，其中的每一段概要信息都记载着，在某个采样时刻，正在执行的 Go 代码以及堆内存的使用情况，这里包含已分配和已释放的字节数量和对象数量

  • 对 阻塞概要文件来说，其中的每一段概要信息，都代表着 Go 程序中的一个 goroutine 阻塞事件。

Note: 在默认情况下，这些概要文件中的信息并不是普通的文件，它们都是以二进制的形式展现的。如果你使用一个常规的文件编辑器查看它们的话，那么肯定会看到一堆 乱码。

查看这些概要文件包含的信息，就需要使用 go tool pprof 这个工具了。我们可以通过它进入一个基于命令行的交互式界面，并对指定的概要文件进行查询。就像下面这样：

1
2
3
4
5
6

$ go tool pprof cpuprofile.out
Type: cpu
Time: Nov 9, 2018 at 4:31pm (CST)
Duration: 7.96s, Total samples = 6.88s (86.38%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

关于这个工具的具体用法：在交互式界面输入 help + Enter

性能分析数据的采样工作

前面提到了，要分析程序的相关性能指标，如 CPU、Mem、Block 等，就要从与其对应得概要文件入手进行分析，那么这些概要文件数据是怎么得来的呢？ 概要文件不是普通的文件，它又是如何生成的呢？ 来，让我们继续往下看

Go 程序的概要文件时通过 protocol buffers 生成的二进制数据流，或者说字节流。

概括来讲，protocol buffers 是一种数据序列化协议，同时也是一个序列化工具。它可以把一个值，比如一个结构体或者一个字典，转换成一段字节流。 换句话说，protocol buffers 定义和实现了一种“可以让数据在结构形态和扁平形态之间互相转换”的方式。

首先来看看第一个问题吧！

怎样让程序对 CPU 概要信息进行采样？

对这个问题的典型回答：

这需要用到 runtime/pprof 包中的 API。更具体地说，在我们想让程序开始对 CPU 概要信息进行采样的时候，需要调用这个代码包中的 StartCPUProfile 函数，而在停止采样的时候则需要调用该包中的 StopCPUProfile 函数。

问题解析

runtime/pprof.StartCPUProfile 函数（以下简称 StartCPUProfile 函数）在被调用的时候，先会去设定 CPU 概要信息的 采样频率，并会在单独的 goroutine 中进行 CPU 概要信息的收集和输出。

Note: StartCPUProfile 函数设定的采样频率总是固定的，即 100 赫兹。也就是说，每 s 采样 100 次，或者说每 10ms 采样一次。

扩展知识：

赫兹，也称 Hz，是从英文单词“Hertz”（一个英文姓氏）音译过来的一个中文词。它是 CPU 主频的基本单位。

CPU 主频指的是，CPU 内核工作的时钟频率，也常被称为 CPU clock speed。这个时钟频率的倒数即为时钟周期（clock cycle），也就是一个 CPU 内核执行一条运算指令所需的时间，单位是秒。

StartCPUProfile 函数设定的 CPU 概要信息采样频率，相对于现代的 CPU 主频来说是非常低的。这主要有两个方面的原因：

  • 其一：

    过高的采样频率会对 Go 程序的运行效率造成很明显的负面影响。因此，runtime 包中 SetCPUProfileRate 函数在被调用的时候，会保证采样频率不超过 1MHz(兆赫)，也就是说它只允许美 1 微秒最多采样一次。StartCPUProfile 函数正是通过调用这个函数来设定 CPU 概要信息的采样频率的。

  • 其二

    经过大量的实验，Go 语言团队发现 100 Hz 是一个比较合适的设定。因为这样做既可以得到足够多、足够有用的概要信息，又不至于让程序的运行出现停滞。另外，操作系统对高频采样的处理能力也是有限的，一般情况下，超过 500 Hz 就很可能得不到及时的响应了。

    在 StartCPUProfile 函数执行后，一个新启用的 goroutine 将会负责执行 CPU 概要信息的收集和输出，直到 runtime/pprof 包中的 StopCPUProfile 函数被成功调用。

    StopCPUProfile 函数也会调用 runtime.SetCPUProfileRate 函数，并把参数值(也就是采样频率) 设为0。这会让针对 CPU 概要信息的采样工作停止。同时，它也会给负责收集 CPU 概要信息的代码一个 信号，以告知收集工作也需要停止了。

    在接收到这样的信号之后，那部分程序将会把这段时间内收集到的所有 CPU 概要信息，全部写入到我们在调用 StartCPUProfile 函数的时候指定的写入器中。只有在上述操作全部完成之后，StopCPUProfile 函数才会返回。

怎样设定内存概要信息的采样频率？

针对内存概要信息的采样会按照一定比例收集 Go 程序在运行期间的堆内存使用情况。设定内存概要信息采样频率的方法很简单，只要为 runtime.MemProfileRate 变量赋值即可。

这个变量的含义是：平均每分配多少个字节，就对堆内存的使用情况进行一次采样。如果把该变量的值设为 0, Go 语言运行时系统就会完全停止对内存概要信息的采样。该变量的缺省值是 512 KB

Note: 注意，如果你要设定这个采样频率，那么越早设定越好，并且只应该设定一次，否则就可能会对 Go 语言运行时系统的采样工作，造成不良影响。比如，只在 main 函数的开始出设定一次。

在这之后，当我们想获取内存概要信息的时候，还需要调用 runtime/pprof 包中的 WriteHeapProfile 函数。该函数会把收集好的内存概要信息，写入到我们指定的写入器中。

Note: 我们通过 WriteHeapProfile 函数得到的内存概要信息并不是实时的，它是一个快照，是在最近一次的内存垃圾收集工作完成时产生的。如果你想要实时的信息，那么可以调用 runtime.ReadMemStats 函数。不过要特别注意，该函数会引起 Go 语言的短暂停顿。

怎样获取到阻塞概要信息？

我们调用 runtime 包中的 SetBlockProfileRate 函数，即可对阻塞概要信息的采样频率进行设定。该函数有一个名叫 rate 的参数，它是 int 类型的。

这个参数的含义是，只要发现一个阻塞时间的持续时间达到了多少个纳秒，就可以对其进行采样。如果这个参数的值小于或等于0，那么久意味着 Go 语言运行时系统将会完全停止对阻塞概要信息的采样。

在 runtime 包中，还有一个名叫 blockprofilerate 的包级私有变量，它是 uint64 类型的。这个变量的含义是，只要发现一个阻塞事件的持续时间跨越了多少个 CPU 时钟周期，就可以对其进行采样。 (与 rate 参数很相似，其区别仅仅在于单位不同)

另一方面，当我们需要获取阻塞概要信息的时候，需要先调用 runtime/pprof 包中的 Lookup 函数并传入参数值 block，从而得到一个 *runtime/pprof.Profile 类型的值(以下简称 Profile 值)。在这之后，我们还需要调用这个 Profile 值得 WriteTo 方法，以驱使它把概要信息写进我们指定的写入器中。

这个 WriteTo 方法有两个参数，一个参数就是我们刚刚提到的写入器，它是 io.Writer 类型的。而另一个参数则代表了概要信息详细程度的 int 类型参数 debug.

debug 参数主要的可选值有两个，即 0 和 1：

  • 当 debug 为 0 时，通过 WriteTo 方法写进写入器的概要信息仅会包含 go tool pprof 工具所需的内存地址，这些内存地址会以十六进制的形式展现出来。

  • 当 debug 为 1 时，相应的包名、函数名、源码文件路径、代码行号等信息就都会作为注释被加入进去。另外，debug 为 0 时的概要信息，会经由 protocol buffers 转换为字节流。而在 debug 为 1 的时候，WriteTo 方法输出的这些概要信息就是我们可以读懂的普通文本了。

  • 除此之外，debug的值也可以是2。这时，被输出的概要信息也会是普通的文本，并且通常会包含更多的细节。至于这些细节都包含哪些内容，那就要看我们调用 runtime/pprof.Lookup 函数的时候传入的是什么样的参数值了。

runtime/pprof.Lookup 函数的正确调用方式是什么？

runtime/pprof.Lookup 函数的功能是：提供与给定名称相对应的概要信息。这个概要信息会由一个 Profile 值代表。如果该函数返回了一个 nil，那么久说明不存在与给定名称相对应的概要信息。

runtime/pprof 包已经为我们预定义了 6 个概要名称。它们对应的概要信息收集方法和输出方法也都已经准备好了。我们可以直接拿来使用：goroutine、heap、allocs、treadcreate、block 和 mutex。

  • 当我们把 goroutine 传入 Lookup 函数的时候，该函数会利用相应的方法，收集到当前正在使用的所有 goroutine 的堆栈跟踪信息。注意，这样的收集会引起 Go 语言调度器的短暂停顿。

    • 当调用该函数返回的 Profile 值得 WriteTo 方法时，如果参数 debug 的值大于或等于 2，那么该方法就会输出所有 goroutine 的堆栈跟踪信息。这些信息可能会非常多。如果它们占用的空间超过了 64 MB （也就是64兆字节），那么相应的方法就会将超出的部分截掉。

  • 如果 Lookup 函数接到的参数值是 heap，那么它就会收集与堆内存的分配和释放有关的采样信息。这实际上就是我们在前面讨论过的内存概要信息。在我们传入 “allocs” 的时候，后续的操作会与之非常的相似。

    • 在这两种情况下，Lookup 函数返回的 Profile 函数值也会及其相像。只不过，在这两种 Profile 值得 WriteTo 方法被调用时，他们输出的概要信息会有细微的差别，而且这仅仅体现在参数 debug 等于 0 的时候

    • heap 会使得被输出的内存概要信息默认以 在用空间(inuse_space) 的视角呈现，而 allocs 对应的默认视角则是 已分配空间(alloc_space)

      • 在用空间(inuse_space)：指已经分配但还未被释放的内存空间。go tool pprof 工具并不会去理会与已释放空间有关的那部分信息。而在“已分配空间”的视角下，所有的内存分配信息都会被展现出来，无论这些内存空间在采样时是否已被释放。

  • 参数值 threadcreate 会使Lookup函数去收集一些堆栈跟踪信息。这些堆栈跟踪信息中的每一个都会描绘出一个代码调用链，这些调用链上的代码都导致新的操作系统线程产生。这样的Profile值的输出规格也只有两种，取决于我们传给其WriteTo方法的参数值是否大于0。

    • 再说 block 和 mutex。block 代表的是，因争用同步原语而被阻塞的那些代码的堆栈跟踪信息。mutex 代表的是，曾经作为同步原语持有者的那些代码，它们的堆栈跟踪信息。它们的输出规格也都只有两种，取决于debug是否大于0。

这里所说的同步原语，指的是存在于 Go 语言运行时系统内部的的一种底层的同步工具，或者说一种同步机制。

它是直接面向内存地址的，并以异步信号量和原子操作作为实现手段。我们已经熟知的通道、互斥锁、条件变量、”WaitGroup“，以及 Go 语言运行时系统本身，都会利用它来实现自己的功能。

如何为基于 HTTP 协议的网络服务添加性能分析接口？

添加方式如下：

先在程序中导入 net/http/pprof 代码包，就像这样：

1

import _ "net/http/pprof"

然后，启动网络服务并开始监听，比如：

1

log.Println(http.ListenAndServer("localhost:8082", nil))

在运行这个程序之后，我们就可以通过在网络浏览器中访问 http://localhost:8082/debug/pprof 这个地址看到一个简约的网页。

Note:

  • /debug/pprof/heap 路径下，可以接收一个名叫 gc 的查询参数，它用于控制是否在获取概要信息之前强制执行一次垃圾回收，只要它的值大于 0，程序就会这样做。

  • /debug/pprof/profile 路径下，可以接收一个名为 seconds 的查询参数。该参数的含义是，采样工作需要持续多少秒。默认(缺省) 30s。 例如：go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60

  • /debug/pprof/trace 被访问时，程序主要会利用 runtime/trace 代码包中的 API 来处理我们的请求

    • 更具体地说，程序会先调用 trace.Start 函数，然后再查询参数 seconds 指定的持续时间之后再调用 trace.Stop 函数。这里的 seconds 的缺省值是 1s。

定制路由：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20

mux := http.NewServeMux()
pathPrefix := "/d/pprof/"
mux.HandleFunc(pathPrefix,
	func(w http.ResponseWriter, r *http.Request) {
		name := strings.TrimPrefix(r.URL.Path, pathPrefix)
		if name != "" {
			pprof.Handler(name).ServeHTTP(w, r)
			return
		}
		pprof.Index(w, r)
	})
mux.HandleFunc(pathPrefix+"cmdline", pprof.Cmdline)
mux.HandleFunc(pathPrefix+"profile", pprof.Profile)
mux.HandleFunc(pathPrefix+"symbol", pprof.Symbol)
mux.HandleFunc(pathPrefix+"trace", pprof.Trace)

server := http.Server{
	Addr:    "localhost:8083",
	Handler: mux,
}

扩展问题

问题：runtime/trace 代码包的功用是什么？

Package trace contains facilities(实施) for programs to generate traces for the Go execution tracer(执行追踪器).

总结

Go 语言的运行时系统会根据要求对程序的相关指标进行多次采样，并对采样的结果进行组织和整理，最后形成一份完整的性能分析报告。 而我们需要理解以 采样、收集、输出 为代表的一系列操作步骤，以及每一种概要信息都代表了什么，它们分别都包含了什么样的内容。

Click Here for Demo Code

See Also

Thanks to the authors 🙂