Golang程序性能分析（一）pprof和go-torch

前言

最近計劃用三篇文章講述一下Golang應(yīng)用性能分析，本文是第一篇，先來介紹Go語言自帶的性能分析庫pprof怎么使用，后面兩篇會講解怎么用pprof對Echo或者Gin框架開發(fā)的應(yīng)用進(jìn)行性能分析以及如何使用pprof對gRPC?服務(wù)進(jìn)行性能分析。

有興趣追更的同學(xué)歡迎微信關(guān)注「網(wǎng)管叨bi叨」

Golang是一個非常注重性能的語言，因此語言的內(nèi)置庫里就自帶了性能分析庫pprof。

性能分析和采集在計算機性能調(diào)試領(lǐng)域使用的術(shù)語是profile，或者有時候也會使用profiling代表性能分析這個行為。所以pprof名字里的prof來源于對單詞profile的縮寫，profile這個單詞的原意是畫像，那么針對程序性能的畫像就是應(yīng)用使用 CPU 和內(nèi)存等等這些資源的情況。都是哪些函數(shù)在使用這些資源？每個函數(shù)使用的比例是多少？

在Go 語言中，主要關(guān)注的程序運行情況包括以下幾種：

• CPU profile：報告程序的 CPU 使用情況，按照一定頻率去采集應(yīng)用程序在 CPU 和寄存器上面的數(shù)據(jù)
• Memory Profile（Heap Profile）：報告程序的內(nèi)存使用情況
• Block Profile：報告導(dǎo)致阻塞的同步原語的情況，可以用來分析和查找鎖的性能瓶頸
• Goroutine Profile：報告 goroutines 的使用情況，有哪些 goroutine，它們的調(diào)用關(guān)系是怎樣的

工具型應(yīng)用的性能分析

如果你的應(yīng)用是工具類應(yīng)用，執(zhí)行完任務(wù)就結(jié)束退出，可以使用 `runtime/pprof` ^[1]庫。

比如要想進(jìn)行 CPU Profiling，可以調(diào)用 pprof.StartCPUProfile() 方法，它會對當(dāng)前應(yīng)用程序進(jìn)行CPU使用情況分析，并寫入到提供的參數(shù)中（w io.Writer），要停止調(diào)用 StopCPUProfile() 即可。

去除錯誤處理只需要三行內(nèi)容，一般把部分內(nèi)容寫在 main.go 文件中，應(yīng)用程序啟動之后就開始執(zhí)行：

f,?err?:=?os.Create(*cpuprofile)
...
pprof.StartCPUProfile(f)
defer?pprof.StopCPUProfile()

應(yīng)用執(zhí)行結(jié)束后，就會生成一個文件，保存了我們應(yīng)用的 CPU使用情況數(shù)據(jù)。

想要獲得內(nèi)存的數(shù)據(jù)，直接使用 WriteHeapProfile 就行，不用 start 和 stop 這兩個步驟了：

f,?err?:=?os.Create(*memprofile)
pprof.WriteHeapProfile(f)
f.Close()

我們的文章會把重點篇幅放在服務(wù)型應(yīng)用的性能分析，所以關(guān)于工具型應(yīng)用的性能分析就說這么多。

服務(wù)型應(yīng)用性能分析

如果你的應(yīng)用是一直運行的，比如 web 應(yīng)用或者gRPC服務(wù)等，那么可以使用 net/http/pprof 庫，它能夠在應(yīng)用提供 HTTP 服務(wù)時進(jìn)行分析。

如果使用了默認(rèn)的 http.DefaultServeMux（通常是代碼直接使用 http.ListenAndServe("0.0.0.0:8000", nil)），只需要在代碼中添加一行，匿名引用net/http/pprof：

import?_?"net/http/pprof"

如果你使用自定義的 ServerMux復(fù)用器，則需要手動注冊一些路由規(guī)則：

r.HandleFunc("/debug/pprof/",?pprof.Index)
r.HandleFunc("/debug/pprof/heap",?pprof.Index)
r.HandleFunc("/debug/pprof/cmdline",?pprof.Cmdline)
r.HandleFunc("/debug/pprof/profile",?pprof.Profile)
r.HandleFunc("/debug/pprof/symbol",?pprof.Symbol)
r.HandleFunc("/debug/pprof/trace",?pprof.Trace)

注冊完后訪問http://localhost/debug/pprof端點，它會得到類似下面的頁面內(nèi)容：

Types?of?profiles?available:
Count?Profile
//?下面是一些可訪問的/debug/pprof/目錄下的路由
2?allocs
0?block
0?cmdline
36?goroutine
2?heap
0?mutex
0?profile
13?threadcreate
0?trace
full?goroutine?stack?dump
Profile?Descriptions:

//?下面是對上面那些路由頁面里展示的性能分析數(shù)據(jù)的解釋
allocs:?A?sampling?of?all?past?memory?allocations
block:?Stack?traces?that?led?to?blocking?on?synchronization?primitives
cmdline:?The?command?line?invocation?of?the?current?program
goroutine:?Stack?traces?of?all?current?goroutines
heap:?A?sampling?of?memory?allocations?of?live?objects.?You?can?specify?the?gc?GET?parameter?to?run?GC?before?taking?the?heap?sample.
mutex:?Stack?traces?of?holders?of?contended?mutexes
profile:?CPU?profile.?You?can?specify?the?duration?in?the?seconds?GET?parameter.?After?you?get?the?profile?file,?use?the?go?tool?pprof?command?to?investigate?the?profile.
threadcreate:?Stack?traces?that?led?to?the?creation?of?new?OS?threads
trace:?A?trace?of?execution?of?the?current?program.?You?can?specify?the?duration?in?the?seconds?GET?parameter.?After?you?get?the?trace?file,?use?the?go?tool?trace?command?to?investigate?the?trace.

這個路徑下幾個需要重點關(guān)注的子頁面有：

• /debug/pprof/profile：訪問這個鏈接會自動進(jìn)行 CPU profiling，持續(xù) 30s，并生成一個文件供下載，可以通過帶參數(shù)?=seconds=60進(jìn)行60秒的數(shù)據(jù)采集
• /debug/pprof/heap：Memory Profiling 的路徑，訪問這個鏈接會得到一個內(nèi)存 Profiling 結(jié)果的文件
• /debug/pprof/block：block Profiling 的路徑
• /debug/pprof/goroutines：運行的 goroutines 列表，以及調(diào)用關(guān)系

直接訪問這些頁面產(chǎn)生的性能分析數(shù)據(jù)我們是分析不過來什么的，Go在1.11版本后在它自帶的工具集go tool里內(nèi)置了pprof工具來分析由pprof庫生成的數(shù)據(jù)文件。

使用go tool pprof

通過上面的設(shè)置可以獲取服務(wù)的性能數(shù)據(jù)后，接下來就可以使用go tool pprof工具對這些數(shù)據(jù)進(jìn)行分析和保存了，一般都是使用pprof通過HTTP訪問上面列的那些路由端點直接獲取到數(shù)據(jù)后再進(jìn)行分析，獲取到數(shù)據(jù)后pprof會自動讓終端進(jìn)入交互模式。在交互模式里pprof為我們提供了不少分析各種指標(biāo)的子命令，在交互模式下鍵入help后就會列出所有子命令。

NOTE pprof子命令的使用方法可以參考 pprof --help 或者 pprof 文檔^[2]。

CPU性能分析

進(jìn)行CPU性能分析直接用go tool pprof訪問上面說的/debug/pprof/profile端點即可，等數(shù)據(jù)采集完會自動進(jìn)入命令行交互模式。

??go?tool?pprof?http://localhost/debug/pprof/profile
Fetching?profile?over?HTTP?from?http://localhost/debug/pprof/profile
Saved?profile?in?/Users/Kev/pprof/pprof.samples.cpu.005.pb.gz
Type:?cpu
Time:?Nov?15,?2020?at?3:32pm?(CST)
Duration:?30.01s,?Total?samples?=?0
No?samples?were?found?with?the?default?sample?value?type.
Try?"sample_index"?command?to?analyze?different?sample?values.
Entering?interactive?mode?(type?"help"?for?commands,?"o"?for?options)
(pprof)

默認(rèn)采集時長是 30s，如果在 url 最后加上 ?seconds=60 參數(shù)可以調(diào)整采集數(shù)據(jù)的時間為 60s。

采集完成我們就進(jìn)入了一個交互式命令行，可以對解析的結(jié)果進(jìn)行查看和導(dǎo)出。可以通過 help 來查看支持的子命令有哪些。

NOTE： 如果pprof用性能數(shù)據(jù)生成分析圖的話、包括后面的go-torch火焰圖都依賴軟件graphviz

Mac 用戶直接brew install graphviz就能安裝，其他系統(tǒng)官網(wǎng)下載頁面也有提供安裝包，請訪問https://graphviz.org/download/

列出最耗時的地方

一個有用的命令是 topN，它列出最耗時間的地方：

(pprof)?top10
130ms?of?360ms?total?(36.11%)
Showing?top?10?nodes?out?of?180?(cum?>=?10ms)
??????flat??flat%???sum%????????cum???cum%
??????20ms??5.56%??5.56%??????100ms?27.78%??encoding/json.(*decodeState).object
??????20ms??5.56%?11.11%???????20ms??5.56%??runtime.(*mspan).refillAllocCache
??????20ms??5.56%?16.67%???????20ms??5.56%??runtime.futex
??????10ms??2.78%?19.44%???????10ms??2.78%??encoding/json.(*decodeState).literalStore
??????10ms??2.78%?22.22%???????10ms??2.78%??encoding/json.(*decodeState).scanWhile
??????10ms??2.78%?25.00%???????40ms?11.11%??encoding/json.checkValid
??????10ms??2.78%?27.78%???????10ms??2.78%??encoding/json.simpleLetterEqualFold
??????10ms??2.78%?30.56%???????10ms??2.78%??encoding/json.stateBeginValue
??????10ms??2.78%?33.33%???????10ms??2.78%??encoding/json.stateEndValue
??????10ms??2.78%?36.11%???????10ms??2.78%??encoding/json.stateInString

每一行表示一個函數(shù)的信息。前兩列表示函數(shù)在 CPU 上運行的時間以及百分比；第三列是當(dāng)前所有函數(shù)累加使用 CPU 的比例；第四列和第五列代表這個函數(shù)以及子函數(shù)運行所占用的時間和比例（也被稱為累加值 cumulative），應(yīng)該大于等于前兩列的值；最后一列就是函數(shù)的名字。如果應(yīng)用程序有性能問題，上面這些信息應(yīng)該能告訴我們時間都花費在哪些函數(shù)的執(zhí)行上。

生成函數(shù)調(diào)用圖

pprof 不僅能打印出最耗時的地方(top)，還能列出函數(shù)代碼以及對應(yīng)的取樣數(shù)據(jù)(list)、匯編代碼以及對應(yīng)的取樣數(shù)據(jù)(disasm)，而且能以各種樣式進(jìn)行輸出，比如 svg、gif、png等等。

其中一個非常便利的是 web 命令，在交互模式下輸入 web，就能自動生成一個 svg 文件，并跳轉(zhuǎn)到瀏覽器打開，生成了一個函數(shù)調(diào)用圖（這個功能需要安裝graphviz后才能使用）。

圖中每個方框?qū)?yīng)應(yīng)用程序運行的一個函數(shù)，方框越大代表函數(shù)執(zhí)行的時間越久（函數(shù)執(zhí)行時間會包含它調(diào)用的子函數(shù)的執(zhí)行時間，但并不是正比的關(guān)系）；方框之間的箭頭代表著調(diào)用關(guān)系，箭頭上的數(shù)字代表被調(diào)用函數(shù)的執(zhí)行時間。

這里還要提兩個比較有用的方法，如果應(yīng)用比較復(fù)雜，生成的調(diào)用圖特別大，看起來很亂，有兩個辦法可以優(yōu)化：

• 使用 web funcName 的方式，只打印和某個函數(shù)相關(guān)的內(nèi)容
• 運行 go tool pprof 命令時加上 --nodefration 參數(shù)，可以忽略內(nèi)存使用較少的函數(shù)，比如--nodefration=0.05表示如果調(diào)用的子函數(shù)使用的 CPU、memory 不超過 5%，就忽略它，不要顯示在圖片中。

分析函數(shù)性能

想更細(xì)致分析，就要精確到代碼級別了，看看每行代碼的耗時，直接定位到出現(xiàn)性能問題的那行代碼。pprof 也能做到，list 命令后面跟著一個正則表達(dá)式，就能查看匹配函數(shù)的代碼以及每行代碼的耗時：

(pprof)?list?podFitsOnNode
Total:?120ms
ROUTINE?========================?k8s.io/kubernetes/plugin/pkg/scheduler.podFitsOnNode?in?/home/cizixs/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/plugin/pkg/scheduler/generic_scheduler.go
?????????0???????20ms?(flat,?cum)?16.67%?of?Total
?????????.??????????.????230:
?????????.??????????.????231://?Checks?whether?node?with?a?given?name?and?NodeInfo?satisfies?all?predicateFuncs.
?????????.??????????.????232:func?podFitsOnNode(pod?*api.Pod,?meta?interface{},?info?*schedulercache.NodeInfo,?predicateFuncs?map[string]algorithm.FitPredicate)?(bool,?[]algorithm.PredicateFailureReason,?error)?{
?????????.??????????.????233:????var?failedPredicates?[]algorithm.PredicateFailureReason
?????????.??????????.????234:????for?_,?predicate?:=?range?predicateFuncs?{
?????????.???????20ms????235:????????fit,?reasons,?err?:=?predicate(pod,?meta,?info)
?????????.??????????.????236:????????if?err?!=?nil?{
?????????.??????????.????237:????????????err?:=?fmt.Errorf("SchedulerPredicates?failed?due?to?%v,?which?is?unexpected.",?err)
?????????.??????????.????238:????????????return?false,?[]algorithm.PredicateFailureReason{},?err
?????????.??????????.????239:????????}
?????????.??????????.????240:????????if?!fit?{

內(nèi)存性能分析

要想獲得內(nèi)存使用 Profiling 信息，只需要把數(shù)據(jù)源修改一下就行（對于 HTTP 方式來說就是修改 url 的地址，從 /debug/pprof/profile 改成 /debug/pprof/heap）：

???go?tool?pprof??http://localhost/debug/pprof/heap????????
Fetching?profile?from?http://localhost/debug/pprof/heap????????
Saved?profile?in?
......
(pprof)

和 CPU Profiling 使用一樣，使用 top N 可以打印出使用內(nèi)存最多的函數(shù)列表：

(pprof)?top
11712.11kB?of?14785.10kB?total?(79.22%)
Dropped?580?nodes?(cum?<=?73.92kB)
Showing?top?10?nodes?out?of?146?(cum?>=?512.31kB)
??????flat??flat%???sum%????????cum???cum%
?2072.09kB?14.01%?14.01%??2072.09kB?14.01%??k8s.io/kubernetes/vendor/github.com/beorn7/perks/quantile.NewTargeted
?2049.25kB?13.86%?27.87%??2049.25kB?13.86%??k8s.io/kubernetes/pkg/api/v1.(*ResourceRequirements).Unmarshal
?1572.28kB?10.63%?38.51%??1572.28kB?10.63%??k8s.io/kubernetes/vendor/github.com/beorn7/perks/quantile.(*stream).merge
?1571.34kB?10.63%?49.14%??1571.34kB?10.63%??regexp.(*bitState).reset
?1184.27kB??8.01%?57.15%??1184.27kB??8.01%??bytes.makeSlice
?1024.16kB??6.93%?64.07%??1024.16kB??6.93%??k8s.io/kubernetes/pkg/api/v1.(*ObjectMeta).Unmarshal
??613.99kB??4.15%?68.23%??2150.63kB?14.55%??k8s.io/kubernetes/pkg/api/v1.(*PersistentVolumeClaimList).Unmarshal
??591.75kB??4.00%?72.23%??1103.79kB??7.47%??reflect.Value.call
??520.67kB??3.52%?75.75%???520.67kB??3.52%??k8s.io/kubernetes/vendor/github.com/gogo/protobuf/proto.RegisterType
??512.31kB??3.47%?79.22%???512.31kB??3.47%??k8s.io/kubernetes/pkg/api/v1.(*PersistentVolumeClaimStatus).Unmarshal

每一列的含義也是類似的，只不過從 CPU 使用時長變成了內(nèi)存使用大小，就不多解釋了。

類似的，web 命令也能生成 svg 圖片在瀏覽器中打開，從中可以看到函數(shù)調(diào)用關(guān)系，以及每個函數(shù)的內(nèi)存使用多少。

需要注意的是，默認(rèn)情況下，統(tǒng)計的是內(nèi)存使用大小，如果執(zhí)行命令的時候加上 --inuse_objects 可以查看每個函數(shù)分配的對象數(shù)；--alloc-space 查看分配的內(nèi)存空間大小。

go-torch 和火焰圖

火焰圖（Flame Graph）是 Bredan Gregg 創(chuàng)建的一種性能分析圖表，因為它的樣子近似火焰而得名。上面的 profiling結(jié)果也轉(zhuǎn)換成火焰圖，這里我們要介紹一個工具：go-torch^[3]。這是 uber 開源的一個工具，可以直接讀取 pprof的 profiling 數(shù)據(jù)，并生成一個火焰圖的 svg 文件。

火焰圖 svg 文件可以通過瀏覽器打開，它對于調(diào)用圖的優(yōu)點是：可以通過點擊每個方塊來分析它上面的內(nèi)容。

火焰圖的調(diào)用順序從下到上，每個方塊代表一個函數(shù)，它上面一層表示這個函數(shù)會調(diào)用哪些函數(shù)，方塊的大小代表了占用 CPU 使用的長短?；鹧鎴D的配色并沒有特殊的意義，默認(rèn)的紅、黃配色是為了更像火焰而已。

go-torch 工具的使用非常簡單，沒有任何參數(shù)的話，它會嘗試從 http://localhost/debug/pprof/profile 獲取 profiling 數(shù)據(jù)。它有三個常用的參數(shù)可以調(diào)整：

• -u --url：要訪問的 URL，這里只是主機和端口部分
• -s --suffix：pprof profile 的路徑，默認(rèn)為 /debug/pprof/profile
• --seconds：要執(zhí)行 profiling 的時間長度，默認(rèn)為 30s

要生成火焰圖，需要事先安裝 FlameGraph^[4]工具，這個工具的安裝很簡單，只要把對應(yīng)的可執(zhí)行文件放到 $PATH 目錄下就行。

總結(jié)

今天的文章把Go語言的性能分析庫pprof的安裝和使用方法大體流程走了一遍，重點講解了一下最常用的幾個性能分析命令以及如何用pprof采集的profile數(shù)據(jù)找出程序里最耗費性能的部分。相信有了pprof的幫助在遇到需要優(yōu)化程序性能的時候我們能有更多的參照指標(biāo)從而有的放矢地對程序性能進(jìn)行優(yōu)化改進(jìn)。

在使用pprof采集數(shù)據(jù)的時候一定要注意下面兩點：

1. 只有在有訪問量的時候才能采集到這些性能指標(biāo)數(shù)據(jù)。我是在公司的壓測環(huán)境對接口壓測時用pprof拿到的數(shù)據(jù)，如果你是在本地運行程序的話最好用Postman或者Jmeter這些工具做個簡單的并發(fā)訪問。
2. 除非有健全的安全策略，否則最好只在測試和壓測環(huán)境加上pprof使用的那些路由，不要在生產(chǎn)環(huán)境上應(yīng)用。

這篇文章就說這么多，后面的文章會介紹怎么在Echo和Gin框架下使用pprof，以及如何用pprof分析gRPC服務(wù)的性能。求關(guān)注、求點贊、求轉(zhuǎn)發(fā)！我是網(wǎng)管，會在這里每周堅持輸出原創(chuàng)，我們下期再見吧。

引用鏈接