go 语言 程序性能剖析

Posted on In

用途

对程序性能进行剖析，可以找到性能的瓶颈、bug、以及对程序进行有目标的优化，从而提高程序的性能，解决程序中存在的问题。

如何对程序进行剖析

  1. 设置要分析的指标，利用工具 (go test)或性能指标API对指标进行剖析，生成对应的概要文件(二进制文件)
  2. 使用分析工具(go tool pprof/ go tool trace)对概要文件进行解析，得到性能指标值的具体信息，这些信息可以以文本，图形的形式展示。
  3. 根据得到性能指标值的具体信息，分析程序性能，查找程序瓶颈或对程序进行优化

要对一个程序进行剖析，必须先生成对应指标的概要文件，然后再用分析工具去解析这个概要文件

概要文件

是Go程序在某一段时间内，对相关指标采样后，得到的概要信息。剖析时，会在程序执行期间进行一些自动抽样，在结束时进行推断，最后把统计结果保存为概要文件，供分析工具使用。

概要文件的格式

概要文件其实就是 由 protocol buffers 生成的二进制数据流，protocol buffers 是一种数据序列化协议，它定义了程序对象如 map，结构体，数组等与字节之间如何相互转化。同时 protocol buffers 不仅仅是协议，也可以作为转化工具来使用，它可以把字节流转化为对象，也可以把对象转化为字节流。protocol buffers 会对生成的字节流进行压缩，它的体积比(JSON，XML)都要更小，所以也更适合用于数据在网上传输

生成概要文件的方法

Go 语言支持多种类型的性能分析，可以通过

  • 使用 go test 配合对应的标识符
  • 使用性能指标API

这两种方式，都可以生成概要文件

有关性能的概要文件

CPU概要文件，内存概要文件，阻塞概要文件，它们可以通过 go test 配合对应的标识符生成，对CPU，内存，阻塞这三个指标进行分析。

Go test 标识生成概要文件

可以使用 go test工具提供的剖析标识对程序进行分析，生成概要文件。不要让多个剖析标识同时运行，它们之间会相互影响，导致分析结果不准确

Cpu 剖析标识

记录占用CPU时间最长的函数，每个运行在CPU上的函数每几毫秒都会遇到系统中断事件，每次中断时，都会记录一个剖析数据

go test gott/fib -cpuprofile=cpu.log -run=None -bench=FibWithMap

堆剖析标识

记录最耗内容的语句，平均每申请512K的内存，就会记录一个剖析数据

go test gott/fib -memprofile=mem.log -run=None -bench=FibWithMap

阻塞剖解标识

记录阻塞goroutine最久的操作，如系统调用，等待锁，管道收发等，每当这些操作阻塞goroutine时，就会记录一个剖析数据

go test gott/fib -blockprofile=block.log -run=None -bench=FibWithMap

解析概要文件

可执行文件

使用以上标识符，除了生成了剖析数据日志(cpu.log/mem.log/block.log)，go test 还会生成对应的可执行程序(fib.test)，以包名做为前缀，后面为.test的文件。为了减少剖析数据日志占用的空间和提高分析效率，分析日志本身并没有记录函数的名称，而是函数的地址，所以需要与之对应的可执行文件，才可以对剖析日志进行数据分析

pprof 分析工具

go tool pprof命令可以用来分析剖析日志，它需要两个基本的参数

  • 剖析文件日志
  • 测试生成的可执行文件
go tool pprof -text -nodecount=10 ./fib.test cpu.log

File: fib.test
Type: cpu
Time: Aug 9, 2021 at 11:30am (CST)
Duration: 1.43s, Total samples = 1.09s (76.02%)
Showing nodes accounting for 1.09s, 100% of 1.09s total
Showing top 10 nodes out of 17
      flat  flat%   sum%        cum   cum%
     0.49s 44.95% 44.95%      0.94s 86.24%  runtime.mapaccess2_fast64
     0.36s 33.03% 77.98%      0.36s 33.03%  runtime.memhash64
     0.12s 11.01% 88.99%      1.06s 97.25%  gott/fib.fibWithMap
     0.06s  5.50% 94.50%      0.06s  5.50%  runtime.add (partial-inline)
     0.03s  2.75% 97.25%      0.03s  2.75%  runtime.bucketShift (inline)
     0.02s  1.83% 99.08%      1.08s 99.08%  gott/fib.BenchmarkFibWithMap
     0.01s  0.92%   100%      0.01s  0.92%  runtime.wbBufFlush1
         0     0%   100%      0.01s  0.92%  runtime.(*bmap).overflow (inline)
         0     0%   100%      0.03s  2.75%  runtime.bucketMask (inline)
         0     0%   100%      0.01s  0.92%  runtime.findrunnable
  • ./fib.test：测试生成的可执行文件，在一般的测试中，当测试完成后，文件就会被丢弃，但在启用剖析标识后，这个文件会被保留，供之后的分析使用
  • -nodecount：限制分析结果输出的行数
  • -text：指定输出的格式

还可以使用-web选项，用于生成函数的有向图，标注有CPU的使用和最热点的函数等信息

go tool pprof -web -nodecount=10 ./fib.test cpu.log

// 使用-web需要安装 GraphViz
brew install graphviz

还可以不加任何选项进入交互界面

go tool pprof cpu.log
Type: cpu
Time: Aug 9, 2021 at 11:30am (CST)
Duration: 1.43s, Total samples = 1.09s (76.02%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

这里只用到了概要文件，没有用到测试生成的可执行文件

性能指标API生成概要文件

除了使用 go test 标识对程序进行性能分析，还可以使用标准库中的 runtime/pprof，runtime/trace，net/http/pprof这三个包中提供的API来对Go程序进行性能分析，生成概要文件。

生成CPU概要文件

StartCPUProfile函数

StartCPUProfile()函数对CPU信息进行定时采样生成概要文件，默认采样频率是100Hz，即每秒采样100次，调用pprof.StartCPUProfile()函数开始进行采样。

StopCPUProfile函数

调用pprof.StopCPUProfile()停止采样。当调用pprof.StartCPUProfile()时，会启用一个新的goroutine，并在其中进行CPU信息的收集

func StopCPUProfile() {
	cpu.Lock()
	defer cpu.Unlock()

	if !cpu.profiling {
		return
	}
	cpu.profiling = false
	runtime.SetCPUProfileRate(0)
	<-cpu.done
}

StopCPUProfile是通过设置SetCPUProfileRate(0)为0，来停止采样的，而pprof.StartCPUProfile 是把runtime.SetCPUProfileRate(100)设置为100来开始采样的

func main() {
	profileName := "cpu_api.log"
	f, err := common.CreateFile("", profileName)
	if err != nil {
		fmt.Printf("CPU profile creation error: %v\n", err)
		return
	}
	defer f.Close()

	pprof.StartCPUProfile(f)
	op.CPULoad() // 耗时的CPU操作
	pprof.StopCPUProfile()
}

pprof.StartCPUProfile(f)：把概要文件写入 cpu_api.log 文件

生成概要文件

go run pprof/cpu/cpu.go

go tool pprof 查看概要文件内容

go tool pprof -text -nodecount=15  cpu_api.log
Type: cpu
Time: Aug 17, 2021 at 3:56pm (CST)
Duration: 1.62s, Total samples = 1.47s (90.66%)
Showing nodes accounting for 1.47s, 100% of 1.47s total
Showing top 15 nodes out of 49
      flat  flat%   sum%        cum   cum%
     1.29s 87.76% 87.76%      1.29s 87.76%  runtime.memmove
     0.06s  4.08% 91.84%      0.06s  4.08%  runtime.usleep
     0.02s  1.36% 93.20%      0.02s  1.36%  runtime.madvise
     0.02s  1.36% 94.56%      0.02s  1.36%  runtime.pthread_kill
     0.02s  1.36% 95.92%      0.10s  6.80%  runtime.slicebytetostring
     0.01s  0.68% 96.60%      1.25s 85.03%  bytes.(*Buffer).WriteString
     0.01s  0.68% 97.28%      0.01s  0.68%  runtime.(*mspan).init (inline)
     0.01s  0.68% 97.96%      0.01s  0.68%  runtime.memclrNoHeapPointers
     0.01s  0.68% 98.64%      0.01s  0.68%  runtime.newArenaMayUnlock
     0.01s  0.68% 99.32%      0.01s  0.68%  runtime.pthread_cond_wait
     0.01s  0.68%   100%      0.05s  3.40%  strconv.FormatInt
         0     0%   100%      0.06s  4.08%  bytes.(*Buffer).String (inline)
         0     0%   100%      0.10s  6.80%  bytes.(*Buffer).grow
         0     0%   100%      0.01s  0.68%  bytes.makeSlice
         0     0%   100%      1.36s 92.52%  gott/common/op.CPULoad

生成内存概要文件

对堆内存的使用进行采样，会按照平均每分配多少个字节(默认为512B)，就对堆内存的使用情况进行一次采样。

MemProfileRate

为 runtime.MemProfileRate 设置采样频率(默认值是512KB)，对其赋0值表示停止采样。

WriteHeapProfile 函数

调用WriteHeapProfile 函数，根据采样频率进行采样，并把收集到的采样信息写入指定文件。

// 源码文件
// WriteHeapProfile is shorthand for Lookup("heap").WriteTo(w, 0).
// It is preserved for backwards compatibility.
func WriteHeapProfile(w io.Writer) error {
	return writeHeap(w, 0)
}

ReadMemStats 函数

WriteHeapProfile(f)函数记录的并不是实时的内存概要信息，而是最近一次内存垃圾工作完成后产生的。要得到实时信息可以使用runtime.ReadMemStats()函数

func main() {
	profileName := "mem_api.log"
	f, err := common.CreateFile("", profileName)
	if err != nil {
		fmt.Printf("memory profile creation error: %v\n", err)
		return
	}
	defer f.Close()
	startMemProfile()
	fib.FibMap(60)
	endMemProfile(f)
}

func startMemProfile() {
	runtime.MemProfileRate = 1
}

func endMemProfile(f *os.File) {
	pprof.WriteHeapProfile(f)
}

调用runtime.MemProfileRate设置每申请1B的内存，就进行采样，调用pprof.WriteHeapProfile(f)把采样信息写入指定的文件mem_api.log中

生成阻塞概要文件

SetBlockProfileRate函数

它在runtime包中，用来设置采样频率，其参数rate的值表示，当阻塞持续多少纳秒后对其进行进行采样。如果这个值小于等于0，则停止采样。

blockprofilerate变量

参数rate的值会被转换为CPU的时钟周期，然后赋值给blockprofilerate，即：实际采样频率为当一个阻塞持续了多少个CPU时钟周期，就对这个事件进行采样

// go 源码文件
func SetBlockProfileRate(rate int) {
	var r int64
	if rate <= 0 {
		r = 0 // disable profiling
	} else if rate == 1 {
		r = 1 // profile everything
	} else {
		// convert ns to cycles, use float64 to prevent overflow during multiplication
		r = int64(float64(rate) * float64(tickspersecond()) / (1000 * 1000 * 1000))
		if r == 0 {
			r = 1
		}
	}

	atomic.Store64(&blockprofilerate, uint64(r))
}

pprof.Lookup(“block”)

用来获取阻塞概要信息，获取信息要调用pprof.Lookup("block")，block做为参数传入，函数会返回一个*pprof.Profile类型的值，对这个值调用WriteTo(w io.Writer, debug int)方法，可以把概要信息写入文件。这个方法的第一个参数传入要写入概要信息的文件，第二个参数debug表示概要信息详细程度

func main() {
	profileName := "block_api.log"
	f, err := common.CreateFile("", profileName)
	if err != nil {
		fmt.Printf("block profile creation error: %v\n", err)
		return
	}
	defer f.Close()
	startBlockProfile()
	fib.FibMap(45)
	stopBlockProfile(f)
}

func startBlockProfile() {
	runtime.SetBlockProfileRate(blockProfileRate)
}

func stopBlockProfile(f *os.File) {
	pprof.Lookup("block").WriteTo(f, debug)
}

debug参数的值

  • 0：生成protocol buffers字节流
  • 1：生成内容可读的普通文本的概要文件，且函数名，包名，源码文件等信息会被做为注释加入进概要文件
  • 2：生成内容可读的普通文本的概要文件，且包括更详细的信息

对于使用参数值1、2生成的概要文件，不能使用 go tool pprof 查看，因为文件不是 protocol格式

pprof.Lookup函数的使用

Lookup(name string)通过给定的name 的值，返回对应的概要信息。如果返回值是 nil，表示不存在与给定名称对应的概要信息。预定义了6个概要名称，分别是goroutine, threadcreate, heap, allocs, block, mutex

函数的返回值是*Profile类型的值，可以通过调用WriteTo(w io.Writer, debug int)方法，把采样的概要信息写入指定的文件中(通过第一个参数设置)，第二个参数表示了写入信息的详细细节程序，值可以是0,1,2(具体代表的内容就是上面小节讲的)。

预定义概要名称的使用

  • goroutine

    此指标可以收集正在使用的所有 goroutine 的堆栈跟踪信息，在调用WriteTo方法时，如果debug的值大于等于2，会把这些信息写入概要文件，文件可能会非常大

  • heap、allocs

    此指标会收集与堆内存的分配和释放有关的采样信息，可以看成是内存概要信息，heap 与 allocs 仅在debug为0的时候会有区别，heap统计的是已经分配但还没有释放的内存空间，allocs展示的是已分配的内存空间。当debug的值大于0时，这两个指标值输出的内容是相同的

  • threadcreate

    此指标会收集堆栈跟踪信息。这些堆栈跟踪信息中的每一个都会描绘出一个代码调用链，这些调用链上的代码都导致新的操作系统线程产生

  • block

    此指标会收集因争用同步原语而被阻塞的那些代码的堆栈跟踪信息

  • mutex

    此指标会收集曾经作为同步原语持有者的那些代码，它们的堆栈跟踪信息

    同步原语可以理解为：通道、互斥锁、条件变量、”WaitGroup”

对于除了 CPU 概要信息之外的其他概要信息，我们都可以通过调用这个函数获取到。

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

在我们编写网络服务程序的时候，使用net/http/pprof包要比直接使用runtime/pprof包方便和实用很多，这个代码包可以为网络服务的监测提供有力的支撑

package main

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

func main() {
	log.Println(http.ListenAndServe("localhost:8082", nil))
}

直接访问http://localhost:8082/debug/pprof 可以看到goroutine,threadcreate,heap, allocs,block,mutex这6个指标的概要信息。它们都配有debug参数，默认值为0，可以通过改变debug的值改变概要信息的详细程度，如 gotroutine的URL是http://localhost:8082/debug/pprof/goroutine?debug=1

当访问http://localhost:8082/debug/pprof/profile 时，程序会执行对 CPU 概要信息的采样，可以通过加入参数seconds来控制对cpu的访问时间(默认是30秒)，当采样结束后，会提示你下载概要文件。你也可以执行下面命令，直接读取概要文件

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

要回答的问题

先写结论，便于接下来的阅读与理解

基准测试与剖析的区别

基准测试可以用来衡量一个程序的性能，如果想让程序运行的更快，或对性能不理想的程序进行提升，基准测试无法给出从哪里可以进行优化。

通过剖析，可以找出程序性能瓶颈所在，从而有针对性的对程序进行优化，提高性能。不要过早的进行优化，97%的场景，都不需要过早优化或根本就不需要优化，我们要做的仅是让程序可以正常运行即可。

剖析是如何进行的

剖析就是在程序执行期间进行一些自动抽样，在结束时进行推断，最后把统计结果保存为剖析数据文件，供剖析工具使用。Go 语言支持多种类型的剖析性能分析，可以通过go test 工具或调用Go的runtime 性能分析API(启用运行时剖析)，对程序进行剖析。

需要对哪些代码进行剖析

要对程序的主要功能，关键部分进行基准测试，然后对其进行剖析，功能测试不应该参与进来，使用 -run=None，禁止功能测试的运行