Go
by smallnest

分析Go程序的Off-CPU性能

性能问题可以分为两种类型：

  • On-CPU: 线程花费在CPU上的时间。
  • Off-CPU: 线程阻塞在I/O、锁、计时器、页交换等场景中的等待时间。

Off-CPU性能分析砖窑用来测量和研究off-CPU时间，所以它不同于CPU profiling只检查线程在CPU上的运行时间，而是专门研究阻塞的线程状态，如下图所示：

On-CPU和Off-CPU

线程既可以因为I/O或者锁的原因离开CPU，但也有一些与当前线程执行无关的原因，包括对CPU资源的高需求导致的非自愿上下文切换和中断。不管是什么原因，如果在工作负载请求期间发生这种情况，则会导致延迟。

Go标准库提供了pprof工具，我们可以使用它方便的分析On-CPU的性能，但是对于Off-CPU性能分析却无能为力。Felix Geisendörfer提供了一个类似pprof的工具fgprof，可以分析Go程序的Off-CPU性能，如果也配置了pprof,可以珠联璧合，一起为On-CPU和Off-CPU的性能提供分析

内容主要翻译整理自fgprof的readme文档。

性能分析的问题

假如给你一个任务，要你优化下面的代码。这是一个简单的程序，在一个循环中调用三个函数。

1
2
3
4
5
6
7
8
9
10
func main() {
	for {
		// http调用函数，可能比较慢
		slowNetworkRequest()
		// 很重的CPU计算
		cpuIntensiveTask()
		// 未知的函数，不知道它执行的快慢
		weirdFunction()
	}
}

一种方式就是包装一个函数，以便计算它们的时间消耗：

1
2
3
4
start := time.Start()
slowNetworkRequest()
fmt.Printf("slowNetworkRequest: %s\n", time.Since(start))
// ...

但是这样做太糟糕了，你需要在每个函数前后都加上统计时间的代码。如果你使用/debug/pprof/profile进行分析的话, 可以修改代码：

1
2
3
4
5
6
7
8
9
import _ "net/http/pprof"
func main() {
	go func() {
		log.Println(http.ListenAndServe(":6060", nil))
	}()
	// <code to profile>
}

然后使用pprof进行分析go tool pprof -http=:6061 http://localhost:6060/debug/pprof/profile?seconds=10:

看起来是cpuIntensiveTask占比最高。但是...真的么？查看我们的日志，看看日志中打印出来的每个函数调用的耗时:

1
2
3
4
5
6
7
slowNetworkRequest: 66.815041ms
cpuIntensiveTask: 30.000672ms
weirdFunction: 10.64764ms
slowNetworkRequest: 67.194516ms
cpuIntensiveTask: 30.000912ms
weirdFunction: 10.105371ms
// ...

实际上是slowNetworkRequest耗时最久，但是上面的火焰图却没反应出来，这个火焰图只显示了那个函数占用CPU的时间最多，也就是On-CPU的性能分析。

再看看另外一个不常用的/debug/pprof/trace，它包含一个synchronization blocking profile,这东东是啥呢？》不管是啥，先生成图看看：

1
2
3
curl -so pprof.trace http://localhost:6060/debug/pprof/trace?seconds=10
go tool trace --pprof=sync pprof.trace > sync.pprof
go tool pprof --http=:6061 sync.pprof

也不对，这张图显示时间主要花在了slowNetworkRequest()上。cpuIntensiveTask()也不见了，可怜的weirdFunction()也没出现。

那么如何都显示I/O和CPU负载的情况呢，使用/debug/fgprof，你可以在http中配置一个handler:

1
2
3
4
5
6
7
8
9
10
11
12
13
import(
	_ "net/http/pprof"
	"github.com/felixge/fgprof"
)
func main() {
	http.DefaultServeMux.Handle("/debug/fgprof", fgprof.Handler())
	go func() {
		log.Println(http.ListenAndServe(":6060", nil))
	}()
	// <code to profile>
}

然后执行go tool pprof --http=:6061 http://localhost:6060/debug/fgprof?seconds=10,最终这三个函数正常的显示了，而且正确显示花在它们上面的时间。

你可以把它配置在你自己的web框架中，如果不支持Handler，可能还得需要你别包装一下。

fgprof在后台启动一个goroutine,以99赫兹的频率读取runtime.GoroutineProfile进行分析。通常它不会对你的程序造成多大的影响，但是调用runtime.GoroutineProfile会导致stopTheWorld()，多少会对多goroutine程序有一些影响，拖慢程序。所以建议你在测试环境中多测测它的影响，之后在决定要不要部署到线上。

参考文档

  1. http://www.brendangregg.com/offcpuanalysis.html
  2. https://github.com/felixge/fgprof