快捷導航

Go 庫性能分析工具pprof

更新時間：2022年12月15日 10:50:06 作者：小馬別過河

這篇文章主要為大家介紹了Go 庫性能分析工具pprof，有需要的朋友可以借鑒參考下，希望能夠有所幫助，祝大家多多進步，早日升職加薪

場景

我們一般沒必要過度優(yōu)化 Go 程序性能。但是真正需要時，Go 提供的 pprof 工具能幫我們快速定位到問題。比如，我們團隊之前有一個服務(wù)，在本地和測試環(huán)境沒問題，一到灰度環(huán)境，就報 cpu 負載過高，后經(jīng)排查，發(fā)現(xiàn)某處代碼死循環(huán)了。我把代碼簡化成如下：

// 處理某些業(yè)務(wù)，真實的代碼中這個死循環(huán)很隱蔽
func retrieveSomeThing() {
	for {}
}
// 處理其他的一些業(yè)務(wù)，無意義，用于后續(xù)做例子
func doSomeThing() {
	do1()
	for i := 0; i < 200000000; i++ {}
	do2()
}
// 無意義
func do1() {
	for i := 0; i < 200000000; i++ {}
}
// 無意義
func do2() {
	for i := 0; i < 200000000; i++ {}
}
func main() {
	go retrieveSomeThing()
  go doSomeThing()
	// 阻塞一下
	time.Sleep(3 * time.Second)
}

解決問題前，先介紹下 pprof。

pprof

pprof 包會輸出運行時的分析數(shù)據(jù)(profiling data)，這些數(shù)據(jù)可以被 pprof 的可視化工具解析。Go 標準庫主要提供了兩個包：

runtime/pprof 通過寫入到文件的方式暴露 profile 數(shù)據(jù)；
net/http/pprof 通過 http 服務(wù)暴露 profile 數(shù)據(jù)，適用于守護進程。

生成 profile 文件

CPU 性能分析

在 runtime/pprof 中，使用StartCPUProfile開啟 CPU 性能分析。退出程序前，需要調(diào)用StopCPUProfile把采樣數(shù)據(jù) flush 到輸出文件。

采樣的頻率默認是 100 Hz（每秒 100 次）。

// 輸出到標準輸出，一般是指定文件
if err := pprof.StartCPUProfile(os.Stdout); err != nil {
    log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()

內(nèi)存性能分析

調(diào)用 WriteHeapProfile 開啟內(nèi)存性能分析：

// 輸出到標準輸出，一般是指定文件
if err := pprof.WriteHeapProfile(os.Stdout); err != nil {
    log.Fatal("could not write memory profile: ", err)
}
}

分析 profile 文件 && 優(yōu)化代碼

以開篇的代碼為例，由于是 CPU 過載，我們可以在 main 函數(shù)開啟 CPU Profile：

// 通過參數(shù)指定 cpu profile 輸出的文件
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
func main() {
	flag.Parse()
	if *cpuprofile != "" {
		f, err := os.Create(*cpuprofile)
		if err != nil {
			log.Fatal("could not create CPU profile: ", err)
		}
		// 開啟 CPU 分析
		if err := pprof.StartCPUProfile(f); err != nil {
			log.Fatal("could not start CPU profile: ", err)
		}
		defer pprof.StopCPUProfile()
	}
	// 業(yè)務(wù)代碼
	go retrieveSomeThing()
  go doSomeThing()
	// 模擬阻塞
	time.Sleep(5 * time.Second)
}

我們執(zhí)行命令，輸出 profile 文件到 cpu.prof。

go run main.go -cpuprofile cpu.prof

go tool pprof

Go 提供性能解析工具：go tool pprof。我們使用 go tool 打開 profile 文件。

> go tool pprof cpu.prof 
Type: cpu
Time: Nov 16, 2022 at 1:40pm (CST)
Duration: 5.17s, Total samples = 4.54s (87.75%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

這是個交互式的界面，輸入help可以查看所有命令。

top 命令

我們使用 topN 命令，查看根據(jù) flat 從大到小排序的前 N 條數(shù)據(jù)。

(pprof) top10
Showing nodes accounting for 4650ms, 100% of 4650ms total
      flat  flat%   sum%        cum   cum%
    4220ms 90.75% 90.75%     4450ms 95.70%  main.retrieveSomeThing
     230ms  4.95% 95.70%      230ms  4.95%  runtime.asyncPreempt
      80ms  1.72% 97.42%      200ms  4.30%  main.doSomeThing
      70ms  1.51% 98.92%       70ms  1.51%  main.do2 (inline)
      50ms  1.08%   100%       50ms  1.08%  main.do1 (inline)

top 命令返回數(shù)據(jù)有5個指標：

flat : 本函數(shù)占用的 CPU 時間，不包括調(diào)用函數(shù)的時間；
flat% : flat 占的百分比；
sum% : 前面 flat% 的總和；
cum : 累計時間，包括調(diào)用的函數(shù)的時間；
cum% : cum 的百分比。

以main.doSomeThing（排第三的函數(shù)）為例子，耗時為：

func doSomeThing() {                   // flat: 80ms  cum: 200ms
	do1()                                // 執(zhí)行時間 50ms
	for i := 0; i < 200000000; i++ {}    // 執(zhí)行時間 80ms
	do2()                                // 執(zhí)行時間 70ms
}

doSomeThing 的 flat 的值為：

for i := 0; i < 200000000; i++ {}的執(zhí)行時間（80ms），不包括do1和do2的時間。

doSomeThing 的 cum 的值為：

cum(200ms) = doSomething的flat(80ms) + do1的flat(50ms) + do2的flat(70ms)

ps: top 可以使用 -cum 參數(shù)來指定，根據(jù) cum 排序。

list 命令

明白了 top 的指標的意思，我們關(guān)注到，排在 top1 的函數(shù)是 retrieveSomeThing?？梢允褂?list 命令，查看 retrieveSomeThing 耗時：

(pprof) list retrieveSomeThing
Total: 4.65s
ROUTINE ======================== main.retrieveSomeThing in /xxxx/pprof_note/pprof/main.go
     4.22s      4.45s (flat, cum) 95.70% of Total
      10ms       10ms      1:package main
         .          .      2:
         .          .      3:import (
         .          .      4:   "flag"
         .          .      5:   "log"
         .          .      6:   "os"
         .          .      7:   "runtime/pprof"
         .          .      8:   "time"
         .          .      9:)
         .          .     10:
         .          .     11:// 處理某些業(yè)務(wù)，真實的代碼中這個死循環(huán)很隱蔽
         .          .     12:func retrieveSomeThing() {
     4.21s      4.44s     13:   for {
         .          .     14:   }
         .          .     15:}
         .          .     16:
         .          .     17:// 處理其他的一些業(yè)務(wù)，無意義，用于后續(xù)做例子
         .          .     18:func doSomeThing() {

我們定位到13行需要優(yōu)化。