分析Go程序的Off-CPU性能|转载鸟窝的博客

2021年2月3日 0 条评论 759 次阅读 0 人点赞

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

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

Off-CPU性能分析砖窑用来测量和研究off-CPU时间,所以它不同于CPU profiling只检查线程在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文档。

性能分析的问题

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

func main() {
	for {
		// http调用函数,可能比较慢
		slowNetworkRequest()
		// 很重的CPU计算
		cpuIntensiveTask()
		// 未知的函数,不知道它执行的快慢
		weirdFunction()
	}
}

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

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

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

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占比最高。但是...真的么?查看我们的日志,看看日志中打印出来的每个函数调用的耗时:

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,这东东是啥呢?》不管是啥,先生成图看看:

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:

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程序有一些影响,拖慢程序。所以建议你在测试环境中多测测它的影响,之后在决定要不要部署到线上。

兰陵美酒郁金香

大道至简 Simplicity is the ultimate form of sophistication.

文章评论(0)

你必须 登录 才能发表评论