【實踐】golang pprof 實戰-CPU,heap,alloc,goroutine,mutex,block

前言

如果要說在 golang 開發過程進行性能調優，pprof 一定是一個大殺器般的工具。但在網上找到的教程都偏向簡略，難尋真的能應用于實戰的教程。這也無可厚非，畢竟 pprof 是當程式占用資源異常時才需要啟用的工具，而我相信大家的編碼水準和排場問題的能力是足夠高的，一般不會寫出性能極度堪憂的程式，且即使發現有一些資源異常占用，也會通過排查代碼快速定位，這也導緻 pprof 需要上戰場的機會少之又少。即使大家有心想學習使用 pprof，卻也常常相忘于江湖。

既然如此，那我就送大家一個性能極度堪憂的“炸彈”程式吧！

這程式沒啥正經用途缺極度占用資源，基本覆寫了常見的性能問題。本文就是希望讀者能一步一步按照提示，使用 pprof 定位這個程式的的性能瓶頸所在，借此學習 pprof 工具的使用方法。

是以，本文是一場“實驗課”而非“理論課”，請讀者騰出時間，腳踏實地，一步一步随實驗步驟進行操作，這會是一個很有趣的冒險，不會很無聊，希望你能喜歡。

實驗準備

這裡假設你有基本的 golang 開發功底，擁有 golang 開發環境并配置了 $GOPATH，能熟練閱讀簡單的代碼或進行簡單的修改，且知道如何編譯運作 golang 程式。此外，需要你大緻知道 pprof 是幹什麼的，有一個基本印象即可，你可以花幾分鐘時間讀一下《Golang 大殺器之性能剖析 PProf》的開頭部分，這不會耽誤太久。

此外由于你需要運作一個“炸彈”程式，請務必確定你用于做實驗的機器有充足的資源，你的機器至少需要：

2 核 CPU；
2G 記憶體。

注意，以上隻是最低需求，你的機器配置能高于上述要求自然最好。實際運作“炸彈”時，你可以關閉電腦上其他不必要的程式，甚至 IDE 都不用開，我們的實驗操作基本上是在指令行裡進行的。

此外，務必確定你是在個人機器上運作“炸彈”的，能接受機器當機重新開機的後果（雖然這發生的機率很低）。請你務必不要在危險的邊緣試探，比如線上上伺服器運作這個程式。

可能說得你都有點害怕了，為打消你顧慮，我可以劇透一下“炸彈”的情況，讓你安心：

程式會占用約 2G 記憶體；
程式占用 CPU 最高約 100%（總量按“核數 * 100%”來算）；
程式不涉及網絡或檔案讀寫；
程式除了吃資源之外沒有其他危險操作。

且程式所占用的各類資源，均不會随着運作時間的增長而增長，換句話說，隻要你把“炸彈”啟動并正常運作了一分鐘，就基本确認安全了，之後即使運作幾天也不會有更多的資源占用，除了有點費電之外。

擷取“炸彈”

炸彈程式的代碼我已經放到了 GitHub 上，你隻需要在終端裡運作

go get

便可擷取，注意加上

-d

參數，避免下載下傳後自動安裝：

go get -d github.com/wolfogre/go-pprof-practice
cd $GOPATH/src/github.com/wolfogre/go-pprof-practice

複制

我們可以簡單看一下

main.go

檔案，裡面有幾個幫助排除性能調問題的關鍵的的點，我加上了些注釋友善你了解，如下：

package main

import (
    // 略
    _ "net/http/pprof" // 會自動注冊 handler 到 http server，友善通過 http 接口擷取程式運作采樣報告
    // 略
)

func main() {
    // 略

    runtime.GOMAXPROCS(1) // 限制 CPU 使用數，避免過載
    runtime.SetMutexProfileFraction(1) // 開啟對鎖調用的跟蹤
    runtime.SetBlockProfileRate(1) // 開啟對阻塞操作的跟蹤

    go func() {
        // 啟動一個 http server，注意 pprof 相關的 handler 已經自動注冊過了
        if err := http.ListenAndServe(":6060", nil); err != nil {
            log.Fatal(err)
        }
        os.Exit(0)
    }()

    // 略
}

複制

除此之外的其他代碼你一律不用看，那些都是我為了模拟一個“邏輯複雜”的程式而編造的，其中大多數的問題很容易通過肉眼發現，但我們需要做的是通過 pprof 來定位代碼的問題，是以為了保證明驗的趣味性請不要提前閱讀代碼，可以實驗完成後再看。

接着我們需要編譯一下這個程式并運作，你不用擔心依賴問題，這個程式沒有任何外部依賴。

go build
./go-pprof-practice

複制

運作後注意檢視一下資源是否吃緊，機器是否還能扛得住，堅持一分鐘，如果确認沒問題，咱們再進行下一步。

控制台裡應該會不停的列印日志，都是一些“貓狗虎鼠在不停地吃喝拉撒”的屁話，沒有意義，不用細看。

【實踐】golang pprof 實戰-CPU,heap,alloc,goroutine,mutex,block

使用 pprof

保持程式運作，打開浏覽器通路

http://localhost:6060/debug/pprof/

，可以看到如下頁面：

image

頁面上展示了可用的程式運作采樣資料，分别有：

類型	描述	備注
allocs	記憶體配置設定情況的采樣資訊	可以用浏覽器打開，但可讀性不高
blocks	阻塞操作情況的采樣資訊	可以用浏覽器打開，但可讀性不高
cmdline	顯示程式啟動指令及參數	可以用浏覽器打開，這裡會顯示 ./go-pprof-practice
goroutine	目前所有協程的堆棧資訊	可以用浏覽器打開，但可讀性不高
heap	堆上記憶體使用情況的采樣資訊	可以用浏覽器打開，但可讀性不高
mutex	鎖争用情況的采樣資訊	可以用浏覽器打開，但可讀性不高
profile	CPU 占用情況的采樣資訊	浏覽器打開會下載下傳檔案
threadcreate	系統線程建立情況的采樣資訊	可以用浏覽器打開，但可讀性不高
trace	程式運作跟蹤資訊	浏覽器打開會下載下傳檔案，本文不涉及，可另行參閱《深入淺出 Go trace》

因為 cmdline 沒有什麼實驗價值，trace 與本文主題關系不大，threadcreate 涉及的情況偏複雜，是以這三個類型的采樣資訊這裡暫且不提。除此之外，其他所有類型的采樣資訊本文都會涉及到，且炸彈程式已經為每一種類型的采樣資訊埋藏了一個對應的性能問題，等待你的發現。

由于直接閱讀采樣資訊缺乏直覺性，我們需要借助

go tool pprof

指令來排查問題，這個指令是 go 原生自帶的，是以不用額外安裝。

我們先不用完整地學習如何使用這個指令，畢竟那太枯燥了，我們一邊實戰一邊學習。

以下正式開始。

排查 CPU 占用過高

我們首先通過活動螢幕（或任務管理器、top 指令，取決于你的作業系統和你的喜好），檢視一下炸彈程式的 CPU 占用：

image

可以看到 CPU 占用相當高，這顯然是有問題的，我們使用

go tool pprof

來排場一下：

go tool pprof http://localhost:6060/debug/pprof/profile

複制

等待一會兒後，進入一個互動式終端：

image

輸入 top 指令，檢視 CPU 占用較高的調用：

image

很明顯，CPU 占用過高是

github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat

造成的。

注：為了保證明驗節奏，關于圖中 flat 、 flat% 、 sum% 、 cum 、 cum% 等參數的含義這裡就不展開講了，你可以先簡單了解為數字越大占用情況越嚴重，之後可以在《Golang 大殺器之性能剖析 PProf》等其他資料中深入學習。

輸入

list Eat

，檢視問題具體在代碼的哪一個位置：

image

可以看到，是第 24 行那個一百億次空循環占用了大量 CPU 時間，至此，問題定位成功！

接下來有一個擴充操作：圖形化顯示調用棧資訊，這很酷，但是需要你事先在機器上安裝

graphviz

，大多數系統上可以輕松安裝它：

brew install graphviz # for macos
apt install graphviz # for ubuntu
yum install graphviz # for centos

複制

或者你也可以通路 graphviz 官網尋找适合自己作業系統的安裝方法。

安裝完成後，我們繼續在上文的互動式終端裡輸入

web

，注意，雖然這個指令的名字叫“web”，但它的實際行為是産生一個 .svg 檔案，并調用你的系統裡設定的預設打開 .svg 的程式打開它。如果你的系統裡打開 .svg 的預設程式并不是浏覽器（比如可能是你的代碼編輯器），這時候你需要設定一下預設使用浏覽器打開 .svg 檔案，相信這難不倒你。

你應該可以看到：

image

圖中，

tiger.(*Tiger).Eat

函數的框特别大，箭頭特别粗，pprof 生怕你不知道這個函數的 CPU 占用很高，這張圖還包含了很多有趣且有價值的資訊，你可以多看一會兒再繼續。

至此，這一小節使用 pprof 定位 CPU 占用的實驗就結束了，你需要輸入

exit

退出 pprof 的互動式終端。

為了友善進行後面的實驗，我們修複一下這個問題，不用太麻煩，注釋掉相關代碼即可：

func (t *Tiger) Eat() {
    log.Println(t.Name(), "eat")
    //loop := 10000000000
    //for i := 0; i < loop; i++ {
    //  // do nothing
    //}
}

複制

之後修複問題的的方法都是注釋掉相關的代碼，不再贅述。你可能覺得這很粗暴，但要知道，這個實驗的重點是如何使用 pprof 定位問題，我們不需要花太多時間在改代碼上。

排查記憶體占用過高

重新編譯炸彈程式，再次運作，可以看到 CPU 占用率已經下來了，但是記憶體的占用率仍然很高：

image

我們再次運作使用 pprof 指令，注意這次使用的 URL 的結尾是 heap：

go tool pprof http://localhost:6060/debug/pprof/heap

複制

再一次使用

top

、

list

來定問問題代碼：

image

可以看到這次出問題的地方在

github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal

，函數内容如下：

func (m *Mouse) Steal() {
    log.Println(m.Name(), "steal")
    max := constant.Gi
    for len(m.buffer) * constant.Mi < max {
        m.buffer = append(m.buffer, [constant.Mi]byte{})
    }
}

複制

可以看到，這裡有個循環會一直向 m.buffer 裡追加長度為 1 MiB 的數組，直到總容量到達 1 GiB 為止，且一直不釋放這些記憶體，這就難怪會有這麼高的記憶體占用了。

使用

web

來檢視圖形化展示，可以再次确認問題确實出在這裡：

image

現在我們同樣是注釋掉相關代碼來解決這個問題。

再次編譯運作，檢視記憶體占用：

image

可以看到記憶體占用已經将到了 35 MB，似乎記憶體的使用已經恢複正常，一片祥和。

但是，記憶體相關的性能問題真的已經全部解決了嗎？

排查頻繁記憶體回收

你應該知道，頻繁的 GC 對 golang 程式性能的影響也是非常嚴重的。雖然現在這個炸彈程式記憶體使用量并不高，但這會不會是頻繁 GC 之後的假象呢？

為了擷取程式運作過程中 GC 日志，我們需要先退出炸彈程式，再在重新啟動前賦予一個環境變量，同時為了避免其他日志的幹擾，使用 grep 篩選出 GC 日志檢視：

GODEBUG=gctrace=1 ./go-pprof-practice | grep gc

複制

日志輸出如下：

image

可以看到，GC 差不多每 3 秒就發生一次，且每次 GC 都會從 16MB 清理到幾乎 0MB，說明程式在不斷的申請記憶體再釋放，這是高性能 golang 程式所不允許的。

如果你希望進一步了解 golang 的 GC 日志可以檢視《如何監控 golang 程式的垃圾回收》,為保證明驗節奏，這裡不做展開。

是以接下來使用 pprof 排查時，我們在乎的不是什麼地方在占用大量記憶體，而是什麼地方在不停地申請記憶體，這兩者是有差別的。

由于記憶體的申請與釋放頻度是需要一段時間來統計的，所有我們保證炸彈程式已經運作了幾分鐘之後，再運作指令：

go tool pprof http://localhost:6060/debug/pprof/allocs

複制

同樣使用 top、list、web 大法：

image

可以看到

github.com/wolfogre/go-pprof-practice/animal/canidae/dog.(*Dog).Run

會進行無意義的記憶體申請，而這個函數又會被頻繁調用，這才導緻程式不停地進行 GC:

func (d *Dog) Run() {
    log.Println(d.Name(), "run")
    _ = make([]byte, 16 * constant.Mi)
}

複制

這裡有個小插曲，你可嘗試一下将

16 * constant.Mi

修改成一個較小的值，重新編譯運作，會發現并不會引起頻繁 GC，原因是在 golang 裡，對象是使用堆記憶體還是棧記憶體，由編譯器進行逃逸分析并決定，如果對象不會逃逸，便可在使用棧記憶體，但總有意外，就是對象的尺寸過大時，便不得不使用堆記憶體。是以這裡設定申請 16 MiB 的記憶體就是為了避免編譯器直接在棧上配置設定，如果那樣得話就不會涉及到 GC 了。

我們同樣注釋掉問題代碼，重新編譯執行，可以看到這一次，程式的 GC 頻度要低很多，以至于短時間内都看不到 GC 日志了：

image

排查協程洩露

由于 golang 自帶記憶體回收，是以一般不會發生記憶體洩露。但凡事都有例外，在 golang 中，協程本身是可能洩露的，或者叫協程失控，進而導緻記憶體洩露。

我們在浏覽器裡可以看到，此時程式的協程數已經多達 106 條：

image

雖然 106 條并不算多，但對于這樣一個小程式來說，似乎還是不正常的。為求安心，我們再次是用 pprof 來排查一下：

go tool pprof http://localhost:6060/debug/pprof/goroutine

複制

同樣是 top、list、web 大法：

image

可能這次問題藏得比較隐晦，但仔細觀察還是不難發現，問題在于

github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink

在不停地建立沒有實際作用的協程：

func (w *Wolf) Drink() {
    log.Println(w.Name(), "drink")
    for i := 0; i < 10; i++ {
        go func() {
            time.Sleep(30 * time.Second)
        }()
    }
}

複制

可以看到，Drink 函數每次回釋放 10 個協程出去，每個協程會睡眠 30 秒再退出，而 Drink 函數又會被反複調用，這才導緻大量協程洩露，試想一下，如果釋放出的協程會永久阻塞，那麼洩露的協程數便會持續增加，記憶體的占用也會持續增加，那遲早是會被作業系統殺死的。

我們注釋掉問題代碼，重新編譯運作可以看到，協程數已經降到 4 條了：

image

排查鎖的争用

到目前為止，我們已經解決這個炸彈程式的所有資源占用問題，但是事情還沒有完，我們需要進一步排查那些會導緻程式運作慢的性能問題，這些問題可能并不會導緻資源占用，但會讓程式效率低下，這同樣是高性能程式所忌諱的。

我們首先想到的就是程式中是否有不合理的鎖的争用，我們倒一倒，回頭看看上一張圖，雖然協程數已經降到 4 條，但還顯示有一個 mutex 存在争用問題。

相信到這裡，你已經觸類旁通了，無需多言，開整。

go tool pprof http://localhost:6060/debug/pprof/mutex

複制

同樣是 top、list、web 大法：

image

可以看出來這問題出在

github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl

。但要知道，在代碼中使用鎖是無可非議的，并不是所有的鎖都會被标記有問題，我們看看這個有問題的鎖那兒觸雷了。

func (w *Wolf) Howl() {
    log.Println(w.Name(), "howl")

    m := &sync.Mutex{}
    m.Lock()
    go func() {
        time.Sleep(time.Second)
        m.Unlock()
    }()
    m.Lock()
}

複制

可以看到，這個鎖由主協程 Lock，并啟動子協程去 Unlock，主協程會阻塞在第二次 Lock 這兒等待子協程完成任務，但由于子協程足足睡眠了一秒，導緻主協程等待這個鎖釋放足足等了一秒鐘。雖然這可能是實際的業務需要，邏輯上說得通，并不一定真的是性能瓶頸，但既然它出現在我寫的“炸彈”裡，就肯定不是什麼“業務需要”啦。

是以，我們注釋掉這段問題代碼，重新編譯執行，繼續。

排查阻塞操作

好了，我們開始排查最後一個問題。

在程式中，除了鎖的争用會導緻阻塞之外，很多邏輯都會導緻阻塞。

image

可以看到，這裡仍有 2 個阻塞操作，雖然不一定是有問題的，但我們保證程式性能，我們還是要老老實實排查确認一下才對。

go tool pprof http://localhost:6060/debug/pprof/block

複制

top、list、web，你懂得。

image

可以看到，阻塞操作位于

github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee

：

func (c *Cat) Pee() {
    log.Println(c.Name(), "pee")

    <-time.After(time.Second)
}

複制

你應該可以看懂，不同于睡眠一秒，這裡是從一個 channel 裡讀資料時，發生了阻塞，直到這個 channel 在一秒後才有資料讀出，這就導緻程式阻塞了一秒而非睡眠了一秒。

這裡有個疑點，就是上文中是可以看到有兩個阻塞操作的，但這裡隻排查出了一個，我沒有找到其準确原因，但懷疑另一個阻塞操作是程式監聽端口提供 porof 查詢時，涉及到 IO 操作發生了阻塞，即阻塞在對 HTTP 端口的監聽上，但我沒有進一步考證。

不管怎樣，恭喜你完整地完成了這個實驗。

思考題

另有一些問題，雖然比較重要，但礙于篇幅（其實是我偷懶），就以思考題的形式留給大家了。

每次進入互動式終端，都會提示“type ‘help’ for commands, ‘o’ for options”，你有嘗試過檢視有哪些指令和哪些選項嗎？有重點了解一下“sample_index”這個選項嗎？
關于記憶體的名額，有申請對象數、使用對象數、申請空間大小、使用空間大小，本文用的是什麼名額？如何檢視不同的名額？（提示：在記憶體實驗中，試試檢視、修改“sample_index”選項。）
你有聽說過火焰圖嗎？要不要在試驗中生成一下火焰圖？
main 函數中的 runtime.SetMutexProfileFraction 和 runtime.SetBlockProfileRate 是如何影響名額采樣的？它們的參數的含義是什麼？

最後

礙于我的水準有限，實驗中還有很多奇怪的細節我隻能暫時熟視無睹（比如“排查記憶體占用過高”一節中，為什麼實際申請的是 1.5 GiB 記憶體），如果這些奇怪的細節你也發現了，并痛斥我假裝睜眼瞎，那麼我的目的就達到了……

——還記得嗎，本文的目的是讓你熟悉使用 pprof，消除對它的陌生感，并能借用它進一步得了解 golang。而你通過這次試驗，發現了程式的很多行為不同于你以往的認知或假設，并抱着好奇心，開始向比深處更深處邁進，那麼，我何嘗不覺得這是本文的功德呢？

與君共勉。

寫得非常棒，向原作者緻敬！

作者：狼*

連結：https://blog.wolfogre.com/posts/go-ppof-practice

【實踐】golang pprof 實戰-CPU,heap,alloc,goroutine,mutex,block

目錄

前言

實驗準備

擷取“炸彈”

使用 pprof

排查 CPU 占用過高

排查記憶體占用過高

排查頻繁記憶體回收

排查協程洩露

排查鎖的争用

排查阻塞操作

思考題

最後