深度解密Go語言之 pprof

時間 2019-11-11

標籤深度解密語言 pprof 简体版

原文原文鏈接

目錄html

相信不少人都聽過「雷神 3」關於性能優化的故事。在一個 3D 遊戲引擎的源碼裏，John Carmack 將 1/sqrt(x) 這個函數的執行效率優化到了極致。node

通常咱們使用二分法，或者牛頓迭代法計算一個浮點數的平方根。但在這個函數裏，做者使用了一個「魔數」，根本沒有迭代，兩步就直接算出了平方根。使人歎爲觀止！git

由於它是最底層的函數，而遊戲裏涉及到大量的這種運算，使得在運算資源極其緊張的 DOS 時代，遊戲也能夠流暢地運行。這就是性能優化的魅力！github

工做中，當業務量比較小的時候，用的機器也少，體會不到性能優化帶來的收益。而當一個業務使用了幾千臺機器的時候，性能優化 20%，那就能省下幾百臺機器，一年能省幾百萬。省下來的這些錢，給員工發年終獎，那得多 Happy！golang

通常而言，性能分析能夠從三個層次來考慮：應用層、系統層、代碼層。web

應用層主要是梳理業務方的使用方式，讓他們更合理地使用，在知足使用方需求的前提下，減小無心義的調用；系統層關注服務的架構，例如增長一層緩存；代碼層則關心函數的執行效率，例如使用效率更高的開方算法等。算法

作任何事，都要講究方法。在不少狀況下，迅速把事情最關鍵的部分完成，就能拿到絕大部分的收益了。其餘的一些邊邊角角，能夠慢慢地縫合。一上來就想完成 100%，每每會陷入付出了巨大的努力，卻收穫寥寥的境地。shell

性能優化這件事也同樣，識別出性能瓶頸，會讓咱們付出最小的努力，而獲得最大的回報。segmentfault

Go 語言裏，pprof 就是這樣一個工具，幫助咱們快速找到性能瓶頸，進而進行有針對性地優化。瀏覽器

什麼是 pprof

代碼上線前，咱們經過壓測能夠獲知系統的性能，例如每秒能處理的請求數，平均響應時間，錯誤率等指標。這樣，咱們對本身服務的性能算是有個底。

可是壓測是線下的模擬流量，若是到了線上呢？會遇到高併發、大流量，不靠譜的上下游，突發的尖峯流量等等場景，這些都是不可預知的。

線上忽然大量報警，接口超時，錯誤數增長，除了看日誌、監控，就是用性能分析工具分析程序的性能，找到瓶頸。固然，通常這種情形不會讓你有機會去分析，降級、限流、回滾纔是首先要作的，要先止損嘛。迴歸正常以後，經過線上流量回放，或者壓測等手段，製造性能問題，再經過工具來分析系統的瓶頸。

通常而言，性能分析主要關注 CPU、內存、磁盤 IO、網絡這些指標。

Profiling 是指在程序執行過程當中，收集可以反映程序執行狀態的數據。在軟件工程中，性能分析（performance analysis，也稱爲 profiling），是以收集程序運行時信息爲手段研究程序行爲的分析方法，是一種動態程序分析的方法。

Go 語言自帶的 pprof 庫就能夠分析程序的運行狀況，而且提供可視化的功能。它包含兩個相關的庫：

runtime/pprof
對於只跑一次的程序，例如天天只跑一次的離線預處理程序，調用 pprof 包提供的函數，手動開啓性能數據採集。
net/http/pprof
對於在線服務，對於一個 HTTP Server，訪問 pprof 提供的 HTTP 接口，得到性能數據。固然，實際上這裏底層也是調用的 runtime/pprof 提供的函數，封裝成接口對外提供網絡訪問。

pprof 的做用

pprof 是 Go 語言中分析程序運行性能的工具，它能提供各類性能數據：

allocs 和 heap 採樣的信息一致，不過前者是全部對象的內存分配，而 heap 則是活躍對象的內存分配。

The difference between the two is the way the pprof tool reads there at start time. Allocs profile will start pprof in a mode which displays the total number of bytes allocated since the program began (including garbage-collected bytes).

上圖來自參考資料【wolfogre】的一篇 pprof 實戰的文章，提供了一個樣例程序，經過 pprof 來排查、分析、解決性能問題，很是精彩。

當 CPU 性能分析啓用後，Go runtime 會每 10ms 就暫停一下，記錄當前運行的 goroutine 的調用堆棧及相關數據。當性能分析數據保存到硬盤後，咱們就能夠分析代碼中的熱點了。

內存性能分析則是在堆（Heap）分配的時候，記錄一下調用堆棧。默認狀況下，是每 1000 次分配，取樣一次，這個數值能夠改變。棧(Stack)分配因爲會隨時釋放，所以不會被內存分析所記錄。因爲內存分析是取樣方式，而且也由於其記錄的是分配內存，而不是使用內存。所以使用內存性能分析工具來準確判斷程序具體的內存使用是比較困難的。

阻塞分析是一個很獨特的分析，它有點兒相似於 CPU 性能分析，可是它所記錄的是 goroutine 等待資源所花的時間。阻塞分析對分析程序併發瓶頸很是有幫助，阻塞性能分析能夠顯示出何時出現了大批的 goroutine 被阻塞了。阻塞性能分析是特殊的分析工具，在排除 CPU 和內存瓶頸前，不該該用它來分析。

pprof 如何使用

咱們能夠經過 報告生成、Web 可視化界面、交互式終端 三種方式來使用 pprof。

—— 煎魚《Golang 大殺器之性能剖析 PProf》

runtime/pprof

拿 CPU profiling 舉例，增長兩行代碼，調用 pprof.StartCPUProfile 啓動 cpu profiling，調用 pprof.StopCPUProfile() 將數據刷到文件裏：

import "runtime/pprof"

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
    // …………
        
    pprof.StartCPUProfile(f)
    defer pprof.StopCPUProfile()
    
    // …………
}

net/http/pprof

啓動一個端口（和正常提供業務服務的端口不一樣）監聽 pprof 請求：

import _ "net/http/pprof"

func initPprofMonitor() error {
    pPort := global.Conf.MustInt("http_server", "pprofport", 8080)

    var err error
    addr := ":" + strconv.Itoa(pPort)

    go func() {
        err = http.ListenAndServe(addr, nil)
        if err != nil {
            logger.Error("funcRetErr=http.ListenAndServe||err=%s", err.Error())
        }
    }()

    return err
}

pprof 包會自動註冊 handler，處理相關的請求：

// src/net/http/pprof/pprof.go:71

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

第一個路徑 /debug/pprof/ 下面其實還有 5 個子路徑：

goroutine
threadcreate
heap
block
mutex

啓動服務後，直接在瀏覽器訪問：

http://47.93.238.9:8080/debug/pprof/

就能夠獲得一個彙總頁面：

能夠直接點擊上面的連接，進入子頁面，查看相關的彙總信息。

關於 goroutine 的信息有兩個連接，goroutine 和 full goroutine stack dump，前者是一個彙總的消息，能夠查看 goroutines 的整體狀況，後者則能夠看到每個 goroutine 的狀態。頁面具體內容的解讀能夠參考【大彬】的文章。

點擊 profile 和 trace 則會在後臺進行一段時間的數據採樣，採樣完成後，返回給瀏覽器一個 profile 文件，以後在本地經過 go tool pprof 工具進行分析。

當咱們下載獲得了 profile 文件後，執行命令：

go tool pprof ~/Downloads/profile

就能夠進入命令行交互式使用模式。執行 go tool pprof -help 能夠查看幫助信息。

直接使用以下命令，則不須要經過點擊瀏覽器上的連接就能進入命令行交互模式：

go tool pprof http://47.93.238.9:8080/debug/pprof/profile

固然也是須要前後臺採集一段時間的數據，再將數據文件下載到本地，最後進行分析。上述的 Url 後面還能夠帶上時間參數：?seconds=60，自定義 CPU Profiling 的時長。

相似的命令還有：

# 下載 cpu profile，默認從當前開始收集 30s 的 cpu 使用狀況，須要等待 30s
go tool pprof http://47.93.238.9:8080/debug/pprof/profile
# wait 120s
go tool pprof http://47.93.238.9:8080/debug/pprof/profile?seconds=120     

# 下載 heap profile
go tool pprof http://47.93.238.9:8080/debug/pprof/heap

# 下載 goroutine profile
go tool pprof http://47.93.238.9:8080/debug/pprof/goroutine

# 下載 block profile
go tool pprof http://47.93.238.9:8080/debug/pprof/block

# 下載 mutex profile
go tool pprof http://47.93.238.9:8080/debug/pprof/mutex

進入交互式模式以後，比較經常使用的有 top、list、web 等命令。

執行 top：

獲得四列數據：

列名	含義
flat	本函數的執行耗時
flat%	flat 佔 CPU 總時間的比例。程序總耗時 16.22s, Eat 的 16.19s 佔了 99.82%
sum%	前面每一行的 flat 佔比總和
cum	累計量。指該函數加上該函數調用的函數總耗時
cum%	cum 佔 CPU 總時間的比例

其餘類型，如 heap 的 flat, sum, cum 的意義和上面的相似，只不過計算的東西不一樣，一個是 CPU 耗時，一個是內存大小。

執行 list，使用正則匹配，找到相關的代碼：

list Eat

直接定位到了相關長耗時的代碼處：

執行 web（須要安裝 graphviz，pprof 可以藉助 grapgviz 生成程序的調用圖），會生成一個 svg 格式的文件，直接在瀏覽器裏打開（可能須要設置一下 .svg 文件格式的默認打開方式）：

圖中的連線表明對方法的調用，連線上的標籤表明指定的方法調用的採樣值（例如時間、內存分配大小等），方框的大小與方法運行的採樣值的大小有關。

每一個方框由兩個標籤組成：在 cpu profile 中，一個是方法運行的時間佔比，一個是它在採樣的堆棧中出現的時間佔比（前者是 flat 時間，後者則是 cumulate 時間佔比)；框越大，表明耗時越多或是內存分配越多。

另外，traces 命令還能夠列出函數的調用棧：

除了上面講到的兩種方式（報告生成、命令行交互），還能夠在瀏覽器裏進行交互。先生成 profile 文件，再執行命令：

go tool pprof --http=:8080 ~/Downloads/profile

進入一個可視化操做界面：

點擊菜單欄能夠在：Top/Graph/Peek/Source 之間進行切換，甚至能夠看到火焰圖（Flame Graph）：

它和通常的火焰圖相比恰好倒過來了，調用關係的展示是從上到下。形狀越長，表示執行時間越長。注：我這裏使用的 go 版本是 1.13，更老一些的版本 pprof 工具不支持 -http 的參數。固然也能夠下載其餘的庫查看火焰圖，例如：

go get -u github.com/google/pprof

或者

go get github.com/uber/go-torch

pprof 進階

我在參考資料部分給出了一些使用 pprof 工具進行性能分析的實戰文章，能夠跟着動手實踐一下，以後再用到本身的平時工做中。

Russ Cox 實戰

這部分主要內容來自參考資料【Ross Cox】，學習一下大牛的優化思路。

事情的原由是這樣的，有人發表了一篇文章，用各類語言實現了一個算法，結果用 go 寫的程序很是慢，而 C++ 則最快。而後 Russ Cox 就鳴不平了，哪受得了這個氣？立刻啓用 pprof 大殺器進行優化。最後，程序不只更快，並且使用的內存更少了！

首先，增長 cpu profiling 的代碼：

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(err)
        }
        
        pprof.StartCPUProfile(f)
        defer pprof.StopCPUProfile()
    }
    ...
}

使用 pprof 觀察耗時 top5 的函數，發現一個讀 map 的函數耗時最長：mapaccess1_fast64，而它出如今一個遞歸函數中。

一眼就能看到框最大的 mapacess1_fast64 函數。執行 web mapaccess1 命令，更聚焦一些：

調用 mapaccess1_fast64 函數最多的就是 main.FindLoops 和 main.DFS，是時候定位到具體的代碼了，執行命令：list DFS，定位到相關的代碼。

優化的方法是將 map 改爲 slice，能這樣作的緣由固然和 key 的類型是 int 並且不是太稀疏有關。

The take away will be that for smaller data sets, you shouldn’t use maps where slices would suffice, as maps have a large overhead.

修改完以後，再次經過 cpu profiling，發現遞歸函數的耗時已經不在 top5 中了。可是新增了長耗時函數：runtime.mallocgc，佔比 54.2%，而這和分存分配以及垃圾回收相關。

下一步，增長採集內存數據的代碼：

var memprofile = flag.String("memprofile", "", "write memory profile to this file")

func main() {
    // …………
    
    FindHavlakLoops(cfgraph, lsgraph)
    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal(err)
        }
        pprof.WriteHeapProfile(f)
        f.Close()
        return
    }
    
    // …………
}

繼續經過 top5、list 命令找到內存分配最多的代碼位置，發現這回是向 map 裏插入元素使用的內存比較多。改進方式一樣是用 slice 代替 map，但 map 還有一個特色是能夠重複插入元素，所以新寫了一個向 slice 插入元素的函數：

func appendUnique(a []int, x int) []int {
    for _, y := range a {
        if x == y {
            return a
        }
    }
    return append(a, x)
}

好了，如今程序比最初的時候快了 2.1 倍。再次查看 cpu profile 數據，發現 runtime.mallocgc 降了一些，但仍然佔比 50.9%。

Another way to look at why the system is garbage collecting is to look at the allocations that are causing the collections, the ones that spend most of the time in mallocgc.

所以須要查看垃圾回收到底在回收哪些內容，這些內容就是致使頻繁垃圾回收的「罪魁禍首」。

使用 web mallocgc 命令，將和 mallocgc 相關的函數用矢量圖的方式展示出來，可是有太多樣本量不多的節點影響觀察，增長過濾命令：

go tool pprof --nodefraction=0.1 profile

將少於 10% 的採樣點過濾掉，新的矢量圖能夠直觀地看出，FindLoops 觸發了最多的垃圾回收操做。繼續使用命令 list FindLoops 直接找到代碼的位置。

原來，每次執行 FindLoops 函數時，都要 make 一些臨時變量，這會加劇垃圾回收器的負擔。改進方式是增長一個全局變量 cache，能夠重複利用。壞處是，如今不是線程安全的了。

使用 pprof 工具進行的優化到這就結束了。最後的結果很不錯，基本上能達到和 C++ 同等的速度和同等的內存分配大小。

咱們能獲得的啓發就是先使用 cpu profile 找出耗時最多的函數，進行優化。若是發現 gc 執行比較多的時候，找出內存分配最多的代碼以及引起內存分配的函數，進行優化。

原文很精彩，雖然寫做時間比較久遠（最初寫於 2011 年）了，但仍然值得一看。另外，參考資料【wolfogre】的實戰文章也很是精彩，並且用的招式和這篇文章差很少，可是你能夠運行文章提供的樣例程序，一步步地解決性能問題，頗有意思！

查找內存泄露

內存分配既能夠發生在堆上也能夠在棧上。堆上分配的內存須要垃圾回收或者手動回收（對於沒有垃圾回收的語言，例如 C++），棧上的內存則一般在函數退出後自動釋放。

Go 語言經過逃逸分析會將盡量多的對象分配到棧上，以使程序能夠運行地更快。

這裏說明一下，有兩種內存分析策略：一種是當前的（這一次採集）內存或對象的分配，稱爲 inuse；另外一種是從程序運行到如今全部的內存分配，無論是否已經被 gc 過了，稱爲 alloc。

As mentioned above, there are two main memory analysis strategies with pprof. One is around looking at the current allocations (bytes or object count), called inuse. The other is looking at all the allocated bytes or object count throughout the run-time of the program, called alloc. This means regardless if it was gc-ed, a summation of everything sampled.

加上 -sample_index 參數後，能夠切換內存分析的類型：

go tool pprof -sample_index=alloc_space  http://47.93.238.9:8080/debug/pprof/heap

共有 4 種：

類型	含義
inuse_space	amount of memory allocated and not released yet
inuse_objects	amount of objects allocated and not released yet
alloc_space	total amount of memory allocated (regardless of released)
alloc_objects	total amount of objects allocated (regardless of released)