一文帶你搞懂 Go pprof

本篇文章節選自《Go 語言編程之旅》中的性能分析大殺器 pprof,文章字數有 1w3+ 字,我想應該是目前業界比較全的 pprof 文章了。

希望藉此讓更多的 Go 語言愛好者搞懂 pprof 的使用,以便在成爲救火隊長時,都能夠脫穎而出,成爲團隊核心主力,實現晚上 7 點下班

本文目錄如下:

覺得不錯的話,歡迎點贊和轉發給更多小夥伴們看到,感謝。

前言

應用程序在運行時,總是會出現一些你所意料不到的問題,像是跑着跑着突然報警,監控提示你進程 CPU 使用率過高、內存佔用不斷增大(疑似泄露)、臨時內存大量申請後長時間內不滑,又或是 Goroutine 泄露、出現 Goroutine 數量暴漲,並且持續保持,甚至是莫名其妙在某次迭代發佈後的數小時內出現了應用程序無法提供服務的問題...

這發生起來的話,是多麼的讓人感到擔憂,那麼除了在我們平時要做好各類防護以外,在問題正在發生時,我們又有什麼辦法排查呢,因此在這個章節,我們將介紹排查辦法之一,也就是 Go 語言的性能剖析大殺器 pprof 工具鏈,它是 Go 語言中必知必會的技能點。

pprof 是什麼

在 Go 語言中,pprof 是用於可視化和分析性能分析數據的工具,pprof 以 profile.proto 讀取分析樣本的集合,並生成報告以可視化並幫助分析數據(支持文本和圖形報告)。

而剛剛提到的 profile.proto 是一個 Protobuf v3 的描述文件,它描述了一組 callstack 和 symbolization 信息, 作用是統計分析的一組採樣的調用棧,是很常見的 stacktrace 配置文件格式。

有哪幾種採樣方式

支持什麼使用模式

可以做什麼

其中像是 Goroutine Profiling 這項功能會在實際排查中會經常用到。

因爲很多問題出現時的表象就是 Goroutine 暴增,而這時候我們要做的事情之一就是查看應用程序中的 Goroutine 正在做什麼事情,因爲什麼阻塞了,然後再進行下一步。

介紹和使用

一個簡單的例子

我們新建一個 main.go 文件,用於後續的應用程序分析和示例展示,寫入如下代碼:

var datas []string

func main() {
 go func() {
  for {
   log.Printf("len: %d", Add("Go 夜讀"))
   time.Sleep(time.Millisecond * 10)
  }
 }()

 _ = http.ListenAndServe("0.0.0.0:6060", nil)
}

func Add(str string) int {
 data := []byte(str)
 datas = append(datas, string(data))
 return len(datas)
}

接下來最重要的一步,就是在 import 中添加 _ "net/http/pprof" 的引用,如下:

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

接下來我們運行這個程序,訪問 http://127.0.0.1:6060/debug/pprof/ 地址,檢查是否正常響應。

通過瀏覽器訪問

第一種方式,我們可以直接通過瀏覽器,進行查看,那麼在第一步我們可以先查看總覽頁面,也就是訪問 http://127.0.0.1:6060/debug/pprof/,如下:

/debug/pprof/

Types of profiles available:
Count Profile
3 allocs
0 block
0 cmdline
8 goroutine
3 heap
0 mutex
0 profile
11 threadcreate
0 trace
full goroutine stack dump

如果你在對應的訪問路徑上新增 ?debug=1 的話,就可以直接在瀏覽器訪問,如下:

debug 模式

若不新增 debug 參數,那麼將會直接下載對應的 profile 文件。

再展開來講,在部署環境中,我們爲了網絡安全,通常不會直接對外網暴露 pprof 的相關端口,因此會通過 curlwget 等方式進行 profile 文件的間接拉取。

另外還有一點需要注意,debug 的訪問方式是具有時效性的,在實際場景中,我們常常需要及時將當前狀態下的 profile 文件給存儲下來,便於二次分析。

通過交互式終端使用

第二種方式,我們可以直接通過命令行,來完成對正在運行的應用程序 pprof 的抓取和分析。

CPU Profiling

$ go tool pprof http://localhost:6060/debug/pprof/profile\?seconds\=60
Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=60
Saved profile in /Users/eddycjy/pprof/pprof.samples.cpu.002.pb.gz
Type: cpu
Duration: 1mins, Total samples = 37.25s (61.97%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

執行該命令後,需等待 60 秒(可調整 seconds 的值),pprof 會進行 CPU Profiling,結束後將默認進入 pprof 的命令行交互式模式,可以對分析的結果進行查看或導出。另外如果你所啓動的 HTTP Server 是 TLS 的方式,那麼在調用 go tool pprof 時,需要將調用路徑改爲:go tool pprof https+insecure://localhost:6060/debug/pprof/profile\?seconds\=60

接下來我們輸入查詢命令 top10 ,以此查看對應資源開銷(例如:CPU 就是執行耗時 / 開銷、Memory 就是內存佔用大小)排名前十的函數,如下:

(pprof) top10
Showing nodes accounting for 36.23s, 97.26% of 37.25s total
Dropped 80 nodes (cum <= 0.19s)
Showing top 10 nodes out of 34
      flat  flat%   sum%        cum   cum%  Name
    32.63s 87.60% 87.60%     32.70s 87.79%  syscall.syscall
     0.87s  2.34% 89.93%      0.88s  2.36%  runtime.stringtoslicebyte
     0.69s  1.85% 91.79%      0.69s  1.85%  runtime.memmove
     0.52s  1.40% 93.18%      0.52s  1.40%  runtime.nanotime
     ...
(pprof)

在大多數的情況下,我們可以通過這五列得出一個應用程序的運行情況,知道當前是什麼函數,正在做什麼事情,佔用了多少資源,誰又是佔用資源的大頭,以此來得到一個初步的分析方向。

另外在交互命令行中,pprof 還支持了大量的其它命令,具體可執行 pprof help 查看幫助說明。

Heap Profiling

$ go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /Users/eddycjy/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.011.pb.gz
Type: inuse_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

執行該命令後,能夠很快的拉取到其結果,因爲它不需要像 CPU Profiling 做採樣等待,這裏需要注意的一點是 Type 這一個選項,你可以看到它默認顯示的是 inuse_space,實際上可以針對多種內存概況進行分析,常用的類別如下:

$ go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap
(pprof) top
Showing nodes accounting for 4.01GB, 100% of 4.01GB total
      flat  flat%   sum%        cum   cum%
    4.01GB   100%   100%     4.01GB   100%  main.Add
         0     0%   100%     4.01GB   100%  main.main.func1
$ go tool pprof -alloc_objects http://localhost:6060/debug/pprof/heap
(pprof) top
Showing nodes accounting for 215552550, 100% of 215560746 total
Dropped 14 nodes (cum <= 1077803)
      flat  flat%   sum%        cum   cum%
  86510197 40.13% 40.13%   86510197 40.13%  main.Add
  85984544 39.89% 80.02%   85984544 39.89%  fmt.Sprintf
  43057809 19.97%   100%  215552550   100%  main.main.func1
         0     0%   100%   85984544 39.89%  log.Printf

另外還有 inuse_objects 和 alloc_space 類別,分別對應查看每個函數所分別的對象數量和查看分配的內存空間大小,具體可根據情況選用。

Goroutine Profiling

$ go tool pprof http://localhost:6060/debug/pprof/goroutine
Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine
Saved profile in /Users/eddycjy/pprof/pprof.goroutine.003.pb.gz
Type: goroutine
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

在查看 goroutine 時,我們可以使用traces命令,這個命令會打印出對應的所有調用棧,以及指標信息,可以讓我們很便捷的查看到整個調用鏈路有什麼,分別在哪裏使用了多少個 goroutine,並且能夠通過分析查看到誰纔是真正的調用方,輸出結果如下:

(pprof) traces
Type: goroutine
-----------+-------------------------------------------------------
         2   runtime.gopark
             runtime.netpollblock
             internal/poll.runtime_pollWait
             ...
-----------+-------------------------------------------------------
         1   runtime.gopark
             runtime.netpollblock
             ...
             net/http.ListenAndServe
             main.main
             runtime.main

在調用棧上來講,其展示順序是自下而上的,也就是 runtime.main 方法調用了 main.main 方法,main.main 方法又調用了 net/http.ListenAndServe 方法,這裏對應的也就是我們所使用的示例代碼了,排查起來會非常方便。

每個調用堆棧信息用 ----------- 分割,函數方法前的就是指標數據,像 Goroutine Profiling 展示是就是該方法佔用的 goroutine 的數量。而 Heap Profiling 展示的就是佔用的內存大小,如下:

$ go tool pprof http://localhost:6060/debug/pprof/heap
...
Type: inuse_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) traces
Type: inuse_space
-----------+-------------------------------------------------------
     bytes:  13.55MB
   13.55MB   main.Add
             main.main.func1
-----------+-------------------------------------------------------

實際上 pprof 中的所有功能都會根據不同的 Profile 類型展示不同的對應結果。

Mutex Profiling

怎麼樣的情況下會造成阻塞呢,一般有如下方式:調用 chan(通道)、調用 sync.Mutex (同步鎖)、調用 time.Sleep() 等等。那麼爲了驗證互斥鎖的競爭持有者的堆棧跟蹤,我們可以根據以上的 sync.Mutex 方式,來調整先前的示例代碼,代碼如下:

func init() {
 runtime.SetMutexProfileFraction(1)
}

func main() {
 var m sync.Mutex
 var datas = make(map[int]struct{})
 for i := 0; i < 999; i++ {
  go func(i int) {
   m.Lock()
   defer m.Unlock()
   datas[i] = struct{}{}
  }(i)
 }

 _ = http.ListenAndServe(":6061", nil)
}

需要特別注意的是 runtime.SetMutexProfileFraction 語句,如果未來希望進行互斥鎖的採集,那麼需要通過調用該方法來設置採集頻率,若不設置或沒有設置大於 0 的數值,默認是不進行採集的。

接下來我們進行調用 go tool pprof 進行分析,如下:

$ go tool pprof http://localhost:6061/debug/pprof/mutex
Fetching profile over HTTP from http://localhost:6061/debug/pprof/mutex
Saved profile in /Users/eddycjy/pprof/pprof.contentions.delay.010.pb.gz
Type: delay
Entering interactive mode (type "help" for commands, "o" for options)

我們查看調用 top 命令,查看互斥量的排名:

(pprof) top
Showing nodes accounting for 653.79us, 100% of 653.79us total
      flat  flat%   sum%        cum   cum%
  653.79us   100%   100%   653.79us   100%  sync.(*Mutex).Unlock
         0     0%   100%   653.79us   100%  main.main.func1

接下來我們可以調用 list 命令,看到指定函數的代碼情況(包含特定的指標信息,例如:耗時),若函數名不明確,默認會對函數名進行模糊匹配,如下:

(pprof) list main
Total: 653.79us
ROUTINE ======================== main.main.func1 in /eddycjy/main.go
         0   653.79us (flat, cum)   100% of Total
         .          .     40:  go func(i int) {
         .          .     41:   m.Lock()
         .          .     42:   defer m.Unlock()
         .          .     43:
         .          .     44:   datas[i] = struct{}{}
         .   653.79us     45:  }(i)
         .          .     46: }
         .          .     47:
         .          .     48: err := http.ListenAndServe(":6061", nil)
         .          .     49: if err != nil {
         .          .     50:  log.Fatalf("http.ListenAndServe err: %v", err)
(pprof)

我們可以在輸出的分析中比較準確的看到引起互斥鎖的函數在哪裏,鎖開銷在哪裏,在本例中是第 45 行。

Block Profiling

與 Mutex 的 runtime.SetMutexProfileFraction 相似,Block 也需要調用 runtime.SetBlockProfileRate() 進行採集量的設置,否則默認關閉,若設置的值小於等於 0 也會認爲是關閉。

與上小節 Mutex 相比,主體代碼不變,僅是新增 runtime.SetBlockProfileRate() 的調用,如下:

func init() {
 runtime.SetBlockProfileRate(1)
 ...
}

我們查看調用 top 命令,查看阻塞情況的排名:

$ go tool pprof http://localhost:6061/debug/pprof/block
Fetching profile over HTTP from http://localhost:6061/debug/pprof/block
Saved profile in /Users/eddycjy/pprof/pprof.contentions.delay.017.pb.gz
Type: delay
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 74.54ms, 100% of 74.54ms total
      flat  flat%   sum%        cum   cum%
   74.54ms   100%   100%    74.54ms   100%  sync.(*Mutex).Lock
         0     0%   100%    74.54ms   100%  main.main.func1

同樣的,我們也可以調用 list 命令查看具體的阻塞情況,執行方式和排查模式與先前概述的一致。

查看可視化界面

接下來我們繼續使用前面的示例程序,將其重新運行起來,然後在其它窗口執行下述命令:

$ wget http://127.0.0.1:6060/debug/pprof/profile

默認需要等待 30 秒,執行完畢後可在當前目錄下發現採集的文件 profile,針對可視化界面我們有兩種方式可進行下一步分析:

  1. 方法一(推薦):該命令將在所指定的端口號運行一個 PProf 的分析用的站點。
$ go tool pprof -http=:6001 profile
  1. 方法二:通過 web 命令將以 svg 的文件格式寫入圖形,然後在 Web 瀏覽器中將其打開。
$ go tool pprof profile
Type: cpu
Time: Feb 1, 2020 at 12:09pm (CST)
Duration: 30s, Total samples = 60ms (  0.2%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web

如果出現錯誤提示 Could not execute dot; may need to install graphviz.,那麼意味着你需要安裝 graphviz組件。

另外方法一所運行的站點,實際上包含了方法二的內容(svg 圖片),並且更靈活,因此非特殊情況,我們會直接使用方法一的方式運行站點來做觀察和分析。

剖析內容

通過 pprof 所提供的可視化界面,我們能夠更方便、更直觀的看到 Go 應用程序的調用鏈、使用情況等。另外在 View 菜單欄中,pprof 還支持多種分析方式的切換,如下:

view 菜單欄

接下來我們將基於 CPU Profiling 所抓取的 Profile 進行一一介紹,而其它 Profile 類型的分析模式也是互通的,只要我們瞭解了一種,其餘的也就會了。

Top

top 欄目

該視圖與前面所講解的 top 子命令的作用和含義是一樣的,因此不再贅述。

Graph

graph 欄目

該視圖展示的爲整體的函數調用流程,框越大、線越粗、框顏色越鮮豔(紅色)就代表它佔用的時間越久,開銷越大。相反若框顏色越淡,越小則代表在整體的函數調用流程中,它的開銷是相對較小的。

因此我們可以用此視圖去分析誰纔是開銷大頭,它又是因爲什麼調用流程而被調用的。

Peek

peek 欄目

此視圖相較於 Top 視圖,增加了所屬的上下文信息的展示,也就是函數的輸出調用者 / 被調用者。

Source

source 欄目

該視圖主要是增加了面向源代碼的追蹤和分析,可以看到其開銷主要消耗在哪裏。

Flame Graph

flame graph 概覽

Flame Graph(火焰圖)它是可動態的,調用順序由上到下(A -> B -> C -> D),每一塊代表一個函數、顏色越鮮豔(紅)、區塊越大代表佔用 CPU 的時間更長。同時它也支持點擊塊深入進行分析。

我們選擇頁面上的 main.main.func1 區塊,將會進入到其屬下的下一層級,如下:

進一步查看 flame graph

這樣子我們就可以根據不同函數的多維度層級進行分析,能夠更好的觀察其流轉並發現問題。

通過測試用例做剖析

在上述章節中,我們是通過在應用程序中埋入方法進行採集的,那麼還有一種方式,能夠更精準的剖析到你所想要分析的流程或函數。

首先我們將先前所編寫的 Add 方法挪到獨立的 package 中,命名爲 add.go 文件,然後新建 add_test.go 文件,寫入如下測試用例代碼:

func TestAdd(t *testing.T) {
 _ = Add("Go 夜讀")
}

func BenchmarkAdd(b *testing.B) {
 for i := 0; i < b.N; i++ {
  Add("Go 夜讀")
 }
}

在完成代碼編寫後,我們回到命令行窗口執行如下采集命令:

$ go test -bench=. -cpuprofile=cpu.profile

執行完畢後會在當前命令生成 cpu.profile 文件,然後只需執行 go tool pprof 命令就可以進行查看了,如下圖:

cpu profile

另外除了對 CPU 進行剖析以外,我們還可以調整選項,對內存情況進行分析,如下采集命令:

$ go test -bench=. -memprofile=mem.profile

接下來和上面一樣,執行 go tool pprof 命令進行查看,如下圖:

進一步查看

通過 Lookup 寫入文件做剖析

除了注入 http handler 和 go test 以外,我們還可以在程序中通過 pprof 所提供的 Lookup 方法來進行相關內容的採集和調用。

其一共支持六種類型,分別是:

具體代碼如下:

type LookupType int8

const (
 LookupGoroutine LookupType = iota
 LookupThreadcreate
 LookupHeap
 LookupAllocs
 LookupBlock
 LookupMutex
)

func pprofLookup(lookupType LookupType, w io.Writer) error {
 var err error
 switch lookupType {
 case LookupGoroutine:
  p := pprof.Lookup("goroutine")
  err = p.WriteTo(w, 2)
 case LookupThreadcreate:
  p := pprof.Lookup("threadcreate")
  err = p.WriteTo(w, 2)
 case LookupHeap:
  p := pprof.Lookup("heap")
  err = p.WriteTo(w, 2)
 case LookupAllocs:
  p := pprof.Lookup("allocs")
  err = p.WriteTo(w, 2)
 case LookupBlock:
  p := pprof.Lookup("block")
  err = p.WriteTo(w, 2)
 case LookupMutex:
  p := pprof.Lookup("mutex")
  err = p.WriteTo(w, 2)
 }

 return err
}

接下來我們只需要對該方法進行調用就好了,其提供了 io.Writer 接口,也就是隻要實現了對應的 Write 方法,我們可以將其寫到任何支持地方去,如下:

...
func init() {
 runtime.SetMutexProfileFraction(1)
 runtime.SetBlockProfileRate(1)
}

func main() {
 http.HandleFunc("/lookup/heap", func(w http.ResponseWriter, r *http.Request) {
  _ = pprofLookup(LookupHeap, os.Stdout)
 })
 http.HandleFunc("/lookup/threadcreate", func(w http.ResponseWriter, r *http.Request) {
  _ = pprofLookup(LookupThreadcreate, os.Stdout)
 })
 http.HandleFunc("/lookup/block", func(w http.ResponseWriter, r *http.Request) {
  _ = pprofLookup(LookupBlock, os.Stdout)
 })
 http.HandleFunc("/lookup/goroutine", func(w http.ResponseWriter, r *http.Request) {
  _ = pprofLookup(LookupGoroutine, os.Stdout)
 })
 _ = http.ListenAndServe("0.0.0.0:6060", nil)
}

在上述代碼中,我們將採集結果寫入到了控制檯上,我們可以進行一下驗證,調用 http://127.0.0.1:6060/lookup/heap,控制檯輸出結果如下:

$ go run main.go
heap profile: 0: 0 [0: 0] @ heap/1048576

# runtime.MemStats
# Alloc = 180632
# TotalAlloc = 180632
# Sys = 69928960
# Lookups = 0
...

爲什麼要初始化 net/http/pprof

在我們的例子中,你會發現我們在引用上對 net/http/pprof 包進行了默認的初始化(也就是 _),如果你曾經漏了,或者沒加,你會發現壓根調用不了 pprof 的相關接口,這是爲什麼呢,我們一起看看下面該包的初始化方法,如下:

func init() {
 http.HandleFunc("/debug/pprof/", Index)
 http.HandleFunc("/debug/pprof/cmdline", Cmdline)
 http.HandleFunc("/debug/pprof/profile", Profile)
 http.HandleFunc("/debug/pprof/symbol", Symbol)
 http.HandleFunc("/debug/pprof/trace", Trace)
}

實際上 net/http/pprof 會在初始化函數中對標準庫中 net/http 所默認提供的 DefaultServeMux 進行路由註冊,源碼如下:

var DefaultServeMux = &defaultServeMux
var defaultServeMux ServeMux

func HandleFunc(pattern string, handler func(ResponseWriter, *Request)) {
 DefaultServeMux.HandleFunc(pattern, handler)
}

而我們在例子中使用的 HTTP Server,也是使用的標準庫中默認提供的,因此便完美的結合在了一起,這也恰好也是最小示例的模式。

這時候你可能會注意到另外一個問題,那就是我們的實際項目中,都是有相對獨立的 ServeMux 的,這時候我們只要仿照着將 pprof 對應的路由註冊進去就好了,如下:

 mux := http.NewServeMux()
 mux.HandleFunc("/debug/pprof/", pprof.Index)
 mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
 mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
 mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
 mux.HandleFunc("/debug/pprof/trace", pprof.Trace)

總結

在本文中我們詳細的介紹了 Go 語言中 pprof 的使用,針對一些常用的套件均進行了說明。而 pprof 在我們平時的性能剖析,問題排查上都佔據着非常重要的角色。

在日常只需要根據合理的排查思路,相信你一定能夠根據在 pprof 中的蛛絲馬跡,解決那些或大或小的問題,實現準點下班!

我是煎魚,咱們下期見 :)

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/cmrvIdy7chYdNZ_seI-jWQ