一文帶你搞懂 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 配置文件格式。
有哪幾種採樣方式
-
runtime/pprof:採集程序(非 Server)的指定區塊的運行數據進行分析。
-
net/http/pprof:基於 HTTP Server 運行,並且可以採集運行時數據進行分析。
-
go test:通過運行測試用例,並指定所需標識來進行採集。
支持什麼使用模式
-
Report generation:報告生成。
-
Interactive terminal use:交互式終端使用。
-
Web interface:Web 界面。
可以做什麼
-
CPU Profiling:CPU 分析,按照一定的頻率採集所監聽的應用程序 CPU(含寄存器)的使用情況,可確定應用程序在主動消耗 CPU 週期時花費時間的位置。
-
Memory Profiling:內存分析,在應用程序進行堆分配時記錄堆棧跟蹤,用於監視當前和歷史內存使用情況,以及檢查內存泄漏。
-
Block Profiling:阻塞分析,記錄 Goroutine 阻塞等待同步(包括定時器通道)的位置,默認不開啓,需要調用
runtime.SetBlockProfileRate
進行設置。 -
Mutex Profiling:互斥鎖分析,報告互斥鎖的競爭情況,默認不開啓,需要調用
runtime.SetMutexProfileFraction
進行設置。 -
Goroutine Profiling:Goroutine 分析,可以對當前應用程序正在運行的 Goroutine 進行堆棧跟蹤和分析。
其中像是 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
-
allocs:查看過去所有內存分配的樣本,訪問路徑爲
$HOST/debug/pprof/allocs
。 -
block:查看導致阻塞同步的堆棧跟蹤,訪問路徑爲
$HOST/debug/pprof/block
。 -
cmdline:當前程序的命令行的完整調用路徑。
-
goroutine:查看當前所有運行的 goroutines 堆棧跟蹤,訪問路徑爲
$HOST/debug/pprof/goroutine
。 -
heap:查看活動對象的內存分配情況, 訪問路徑爲
$HOST/debug/pprof/heap
。 -
mutex:查看導致互斥鎖的競爭持有者的堆棧跟蹤,訪問路徑爲
$HOST/debug/pprof/mutex
。 -
profile:默認進行 30s 的 CPU Profiling,得到一個分析用的 profile 文件,訪問路徑爲
$HOST/debug/pprof/profile
。 -
threadcreate:查看創建新 OS 線程的堆棧跟蹤,訪問路徑爲
$HOST/debug/pprof/threadcreate
。
如果你在對應的訪問路徑上新增 ?debug=1
的話,就可以直接在瀏覽器訪問,如下:
debug 模式
若不新增 debug
參數,那麼將會直接下載對應的 profile 文件。
再展開來講,在部署環境中,我們爲了網絡安全,通常不會直接對外網暴露 pprof 的相關端口,因此會通過 curl
、wget
等方式進行 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)
-
flat:函數自身的運行耗時。
-
flat%:函數自身在 CPU 運行耗時總比例。
-
sum%:函數自身累積使用 CPU 總比例。
-
cum:函數自身及其調用函數的運行總耗時。
-
cum%:函數自身及其調用函數的運行耗時總比例。
-
Name:函數名。
在大多數的情況下,我們可以通過這五列得出一個應用程序的運行情況,知道當前是什麼函數,正在做什麼事情,佔用了多少資源,誰又是佔用資源的大頭,以此來得到一個初步的分析方向。
另外在交互命令行中,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
,實際上可以針對多種內存概況進行分析,常用的類別如下:
- 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
- alloc_objects:分析應用程序的內存臨時分配情況。
$ 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,針對可視化界面我們有兩種方式可進行下一步分析:
- 方法一(推薦):該命令將在所指定的端口號運行一個 PProf 的分析用的站點。
$ go tool pprof -http=:6001 profile
- 方法二:通過 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 方法來進行相關內容的採集和調用。
其一共支持六種類型,分別是:
-
goroutine
-
threadcreate
-
heap
-
block
-
mutex
具體代碼如下:
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