往期好文推薦 ⭐️⭐️⭐️:
# golang pprof 監控系列(1) —— go trace 統計原理與使用
# golang pprof監控系列（2） —— memory，block，mutex 使用
# golang pprof 監控系列(3) —— memory，block，mutex 統計原理
# golang pprof 監控系列(4) —— goroutine thread 統計原理
# golang pprof 監控系列(5) —— cpu 佔用率 統計原理
大家好，我是藍胖子，說到golang的效能分析，不得不提的就是其自身擁有的pprof，它提供了從cpu，記憶體，阻塞情況，協程，執行緒，乃至程式執行軌跡trace的分析，可以說相當強大了。
今天我將會用較長的篇幅闡述 應該如何使用pprof工具來 對cpu，記憶體，阻塞情況，協程，執行緒 這幾個維度去進行分析。
其實總結出來Golang pprof的使用方式，可以用下面的思維導圖來表示，
要麼在程式中透過http介面的方式暴露相應的pprof的採集控制介面，要麼就是在程式中透過程式碼開啟對應指標的採集樣本功能，採集一段時間的樣本後生成二進位制檔案，最後透過 go tool pprof 命令去對樣本的資料進行分析。
分析的方式也有兩種，
- 透過命令列開啟一個互動終端
- 透過瀏覽器將二進位制檔案的資訊展示出來
我們可以透過下述的程式碼透過http介面的方式暴露相應的pprof的採集控制介面，
import (
"log"
"net/http"
"net/http/pprof"
"time")
func main() {
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 func() { log.Fatal(http.ListenAndServe(":8080", mux)) }()
time.Sleep(time.Hour)
}
接著訪問下http://localhost:8080/debug/pprof/ 便會出現各種維度指標，可以點選進去檢視具體的指標資訊。如下所示，
接下來我們來分析下各個指標在 http介面或者生成的二進位制檔案 輸出的各種資訊究竟代表什麼含義。
在下面的分析中我會分別的從http介面暴露指標的方式和二進位制檔案的方式分別介紹如何看懂各種指標的輸出資訊。
cpu
cpu在http介面暴露的分析介面中有個profile的連結，點選後，應用程式會採集30s的cpu執行資訊後然後生成一個二進位制檔案，所以本質上對cpu的分析都是透過一個二進位制檔案進行的。
除了上述提到http介面暴露出cpu指標外，我們還可以透過下面的程式碼，在程式中顯示的開啟cpu指標的採集。在這個例子中，我透過busyCpu 方法不斷的進行加法運算來模擬頻繁的cpu操作。
import (
"github.com/pkg/profile"
"log"
"os"
"os/signal"
"syscall")
func main() {
p := profile.Start(profile.CPUProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook,
)
defer p.Stop()
go busyCpu()
c := make(chan os.Signal, 1)
signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
defer signal.Stop(c)
<-c
}
func busyCpu() {
i := uint(1000000)
for {
log.Println("sum number", i, Add(i, i+1))
i++
}
}
func Add(a, b uint) uint {
return a + b
}
啟動終端分析
在得到二進位制檔案後，我們可以使用如下命令來啟動一個互動終端來分析cpu的使用情況，
go tool pprof cpuprofile/cpu.pprof
輸入top命令得到如下結果
(base) ➜ cpu go tool pprof cpuprofile/cpu.pprof
Type: cpu
Time: Mar 4, 2024 at 3:14pm (CST)
Duration: 4.35s, Total samples = 200ms ( 4.60%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 200ms, 100% of 200ms total
Showing top 10 nodes out of 16
flat flat% sum% cum cum%
190ms 95.00% 95.00% 190ms 95.00% syscall.syscall
10ms 5.00% 100% 10ms 5.00% runtime.pthread_cond_signal
0 0% 100% 190ms 95.00% internal/poll.(*FD).Write
0 0% 100% 190ms 95.00% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 190ms 95.00% log.(*Logger).output
0 0% 100% 190ms 95.00% log.Println (inline)
0 0% 100% 190ms 95.00% main.busyCpu
0 0% 100% 190ms 95.00% os.(*File).Write
0 0% 100% 190ms 95.00% os.(*File).write (inline)
0 0% 100% 10ms 5.00% runtime.exitsyscallfast.func1
每個列的含義如下:
flat：函式自身的執行耗時（排除了子函式的呼叫耗時）
flat%：flat執行耗時佔用總的採集樣本的時間和的比例，這裡所有節點執行的flat時間和為200ms。
sum%：命令列返回結果中函式自身和其之上的函式執行的flat時間佔所有采集樣本時間總和的比例。
cum：當前函式和其子函式的呼叫耗時總的執行時間
cum%：cum耗時佔總的採集樣本的時間和的比例。
分析中可以看出主要是列印日誌佔用了比較大的cpu。
在命令列中可以輸入svg，來輸出cpu效能剖析的profile 圖。
(pprof) svg
Generating report in profile001.svg
圖中顯示了函式的呼叫關係，函式框中顯示了函式自身的執行時長flat和其自身及其子函式執行時長cum，箭頭上的時間則是其子函式的cum執行時長，時間越大，箭頭越粗。
將二進位制檔案資訊輸出到瀏覽器上
可以透過如下命令來啟動瀏覽器檢視cpu使用情況，
go tool pprof -http=:8082 cpuprofile/cpu.pprof
火焰圖分析效能問題
透過web介面，我們除了按剛才的top和呼叫耗時影像外，甚至還能透過火焰圖的方式，來檢視cpu呼叫耗時，火焰圖上，函式的呼叫順序是從上往下，函式佔用cpu越長，那麼在火焰圖上的區塊就會越大。 火焰圖中顯示的是cum值。
peek
除了像top那樣輸出函式的耗時情況，還會輸出呼叫函式和被呼叫函式，呼叫順序從上到下。
source
在web介面可以透過source檢視去檢視函式節點的耗時以及它的子呼叫函式中耗時的地方，第一欄時間是flat耗時，第二欄時間是cum耗時。 耗時百分比是cum耗時佔樣本總和的百分比。
記憶體
http介面暴露的控制檯檢視
透過點選heap或者allocs 連結可以檢視記憶體的分配情況，它們的輸出都是一致的，
heap profile: 7: 5536 [110: 2178080] @ heap/1048576
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20
# 0x100d7e0eb runtime.allocm+0x8b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1881
# 0x100d7ea77 runtime.newm+0x37 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2207
# 0x100d7f25f runtime.startm+0x11f /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2491
# 0x100d7f78b runtime.wakep+0xab /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:2590
# 0x100d811cb runtime.resetspinning+0x7b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3222
# 0x100d817d3 runtime.schedule+0x2d3 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:3383
# 0x100d7d6db runtime.mstart1+0xcb /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1419
# 0x100d7d5e3 runtime.mstart0+0x73 /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:1367
# 0x100daba1f runtime.mstart+0xf /Users/lanpangzi/goproject/src/go/src/runtime/asm_arm64.s:117
下面來講下網頁輸出內容的含義
heap profile: 7: 5536 [110: 2178080] @ heap/1048576
輸出的第一行含義分別是:
7 代表 當前活躍的物件個數
5536 代表 當前活躍物件佔用的位元組數
110 代表 所有(包含歷史的物件)物件個數
2178080 代表 所有物件(包含歷史的物件)佔用的物件位元組數
1048576 控制了記憶體取樣的頻率，1048576 是兩倍的記憶體取樣頻率的大小，預設取樣頻率是512kb 即平均每512kb就會取樣一次，注意這個值512kb不是絕對的達到512kb就會進行取樣，而是從一段時間內的取樣來看的一個平均值。
接下來就是函式呼叫堆疊資訊，來看第一行
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20
從左往右看:
2 代表 在該函式棧上當前活躍的物件個數
2304 代表 在該函式棧上當前活躍的物件所佔用的位元組數
方括號內的2 代表 在該函式棧上所有(包含歷史的物件)物件個數
方括號內的2304 代表 在該函式棧上所有(包含歷史的物件)物件所佔用的位元組數
然後是棧上pc暫存器的值。再往後就是具體的棧函式名資訊了。
透過二進位制檔案檢視
我們可以使用如下程式碼生成一個關於記憶體使用情況的二進位制profile檔案，下述程式碼中我用
allocMem 函式不斷對一個位元組陣列進行append操作來模擬記憶體不斷增大的情況。
package main
import (
"github.com/pkg/profile"
"log"
"os"
"os/signal"
"syscall"
"time")
func main() {
p := profile.Start(profile.MemProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook,
)
defer p.Stop()
go allocMem()
c := make(chan os.Signal, 1)
signal.Notify(c, syscall.SIGINT, syscall.SIGTERM)
defer signal.Stop(c)
<-c
}
func allocMem() {
buf := []byte{}
mb := 1024 * 1024
for {
buf = append(buf, make([]byte, mb)...)
log.Println("total allocated memory", len(buf))
time.Sleep(time.Second)
}
}
生成的二進位制檔案，和cpu分析一致，可以透過啟動互動終端或者web瀏覽器去進行檢視，所以啟動終端的方式我這裡就暫時略去了， 講講不同點， 針對於記憶體，pprof在web 瀏覽器介面提供了幾個維度去分析。
inuse_space: 正在使用，尚未釋放的空間
inuse_object: 正在使用，尚未釋放的物件
alloc_space: 所有分配的空間，包含已釋放的
alloc_objects: 所有分配的物件，包含已釋放的
拿inuse_object舉例，效能剖析圖是這樣的，箭頭顯示了正在使用的物件個數，其中 main.allocMem函式自身有一個4MB多的物件，其子函式有4個物件
我們可以根據source 選項也能得到同樣的分析結果，
block
block可用於分析程式鎖mutex，select ，channel通道, wait group 的阻塞行為。
但是block通常是關閉的，需要透過下面程式碼進行開啟，
runtime.SetBlockProfileRate(1)
其中,SetBlockProfileRate 的引數名為rate，rate不同，對block事件的取樣頻率不同
1代表 始終對阻塞事件進行取樣<= 0代表關閉阻塞事件的取樣- 除了上述兩種情況，SetBlockProfileRate 的引數傳遞的將會是一個納秒值。
如果阻塞的時間大於了rate值則直接進行取樣，如果阻塞的時間小於rate，那麼阻塞事件將會有(阻塞時間)/rate 的可能性被採集到。
📢📢📢 注意下block事件的記錄時機為獲取鎖資源或者channel 資源時，進行記錄，也就是發生在lock函式中。
http介面暴露的控制檯檢視
透過點選http介面暴露的pprof控制的block連結，可以檢視程式中block的情況，瀏覽器輸出如下，
--- contention:
cycles/second=1000000000
180001216583 1 @ 0x1002a1198 0x1005159b8 0x100299fc4
# 0x1002a1197 sync.(*Mutex).Lock+0xa7 /Users/lanpangzi/goproject/src/go/src/sync/mutex.go:81
# 0x1005159b7 main.main.func2+0x27 /Users/lanpangzi/goproject/src/go/main/main.go:33
contention 是為這個profile文字資訊取的名字，總之中文翻譯是爭用。
cycles/second 是cpu時鐘每秒鐘的週期數，用它來表示時間也是為了更精確，其實你可以發現在我的機器上每秒是10的9次方個週期，換算成納秒就是1ns一個週期時間了。
接著的180001216583 是阻塞的週期數，其實週期就是cputicks，那麼180001216583除以 cycles/second 即1000000000得到的就是阻塞的秒數了。
接著 1代表阻塞的次數。
無論是阻塞週期時長還是次數，都是一個累加值，即在相同的地方阻塞會導致這個值變大，並且次數會增加。剩下的部分就是函式堆疊資訊了。
使用二進位制檔案檢視
可以透過如下程式碼生成block的二進位制檔案，透過在主協程中使用lock方法後，不釋放鎖資源，啟動子協程，讓子協程同樣使用lock方法模擬系統阻塞的情況。
import (
"fmt"
"github.com/pkg/profile"
"runtime"
"sync"
"time")
/*
*
每次程式鎖阻塞發生時，select 阻塞，channel通道阻塞,
wait group 產生阻塞時就會記錄一次阻塞行為
*/
func main() {
runtime.SetBlockProfileRate(1)
p := profile.Start(profile.BlockProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook)
defer p.Stop()
mLock := sync.Mutex{}
mLock.Lock()
go mockBlock(&mLock)
go mockBlock(&mLock)
time.Sleep(time.Second * 2)
mLock.Unlock()
time.Sleep(time.Second)
fmt.Println("End")
}
func mockBlock(l *sync.Mutex) {
l.Lock()
defer l.Unlock()
fmt.Println("獲取鎖")
}
生成的profile檔案，同樣可以透過命令列和web瀏覽器的方式進行檢視。
這裡我直接取樣瀏覽器的方式瀏覽，
go tool pprof -http=:8083 ./profile/block.pprof
block提供了兩個維度去觀察阻塞事件 ，contention 發生阻塞的事件個數，delay 發生阻塞的時間。
contention 生成的profile圖如下，可以看到發生阻塞的函式是main.mockBlock ，其自身包括其呼叫子函式的阻塞次數是2次。
delay生成的profile 圖如下所示，main.mockBlock其自身包括其呼叫子函式的阻塞時間是4s。
📢📢📢 無論是阻塞次數還是阻塞時間，如果同一個函式發生了阻塞，那麼次數和阻塞時間都會累加上去。
使用 阻塞時間/阻塞次數 能得到平均每次阻塞多長時間。
mutex
mutex 記錄的是持有鎖的時間，注意下它和block的區別，block記錄的是在獲取鎖之前阻塞的時間。並且block還可以記錄channel
mutex 的採集預設情況下也是關閉的，需要用以下程式碼進行開啟，
runtime.SetMutexProfileFraction(1)
其中,SetMutexProfileFraction 的引數名為rate，rate不同，對block事件的取樣頻率不同
1代表 始終對持有鎖事件進行取樣= 0代表關閉阻塞事件的取樣< 0將會把當前的rate值讀取出來> 1將會有1/rate 的持有鎖事件被採集
http介面暴露的控制檯檢視
透過點選http介面暴露的pprof控制的mutex連結，可以檢視程式中鎖持有的的情況，瀏覽器輸出如下，
--- mutex:
cycles/second=1000000812
sampling period=1
180001727833 1 @ 0x100b9175c 0x100e05840 0x100b567ec 0x100b89fc4
# 0x100b9175b sync.(*Mutex).Unlock+0x8b /Users/lanpangzi/goproject/src/go/src/sync/mutex.go:190
# 0x100e0583f main.main+0x19f /Users/lanpangzi/goproject/src/go/main/main.go:39
# 0x100b567eb runtime.main+0x25b /Users/lanpangzi/goproject/src/go/src/runtime/proc.go:255
第一行mutex就是profile文字資訊的名稱了，同樣也和block一樣，採用cpu週期數計時，但是多了一個sampling period ，這個就是我們設定的採用頻率。
接下來的資料都和block類似，180001727833就是鎖持有的週期， 1為解鎖的次數。然後是解鎖的堆疊資訊。
使用二進位制檔案檢視
我們可以透過如下程式碼生成mutex的二進位制檔案，模擬阻塞的情況和block一致，程式碼不同的點是將樣本採集的物件從block替換成了mutex。
package main
import (
"fmt"
"github.com/pkg/profile"
"runtime"
"sync"
"time")
func main() {
runtime.SetMutexProfileFraction(1)
p := profile.Start(profile.MutexProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook)
defer p.Stop()
mLock := sync.Mutex{}
mLock.Lock()
go mockBlock(&mLock)
go mockBlock(&mLock)
time.Sleep(time.Second * 2)
mLock.Unlock()
time.Sleep(time.Second)
fmt.Println("End")
}
func mockBlock(l *sync.Mutex) {
l.Lock()
defer l.Unlock()
fmt.Println("獲取鎖")
}
這裡我同樣採用web瀏覽器的方式去檢視mutext的剖析grapgh，mutex提供了兩個維度去觀察阻塞事件 ，contention 發生持有鎖的事件個數，delay 持有鎖的時間。
以下是contention 維度的圖，可以看到在main方法中進行中持有了一次鎖，在mockBlock方法中也持有了一次鎖。
透過delay 維度可以發現main方法以及其子呼叫函式，持有鎖的時間一共是2s。
goroutine
http介面暴露的控制檯檢視
點選控制介面的goroutine連結，我們會看到在程式中goroutine正在執行的函式堆疊資訊，介面如下，
首先位址列 /debug/pprof/goroutine?debug= 1 代表這是在訪問goroutine指標資訊，debug =1 代表訪問的內容將會以文字可讀的形式展現出來。 debug=0 則是會下載一個goroutine指標資訊的二進位制檔案。 debug = 2 將會把當前所有協程的堆疊資訊以文字可讀形式展示在網頁上。如下圖所示:
debug =2 時的 如上圖所示，41代表協程的id，方括號內running代表了協程的狀態是執行中，接著就是該協程此時的堆疊資訊了。
讓我們再回到debug = 1的分析上面去，剛才分析完了位址列裡的debug引數，接著，我們看輸出的第一行
goroutine profile: total 6 1 @ 0x102ad6c60 0x102acf7f4 0x102b04de0 0x102b6e850 0x102b6e8dc 0x102b6f79c 0x102c27d04 0x102c377c8 0x102d0fc74 0x102bea72c 0x102bebec0 0x102bebf4c 0x102ca4af0 0x102ca49dc 0x102d0b084 0x102d10f30 0x102d176a4 0x102b09fc4 # 0x102b04ddf internal/poll.runtime_pollWait+0x5f /Users/xiongchuanhong/goproject/src/go/src/runtime/netpoll.go:303 # 0x102b6e84f internal/poll.(*pollDesc).wait+0x8f /Users/xiongchuanhong/goproject/src/go/src/internal/poll/fd_poll_runtime.go:84 ......
goroutine profile 表明了這個profile的型別。
total 6 代表此時一共有6個協程。
接著是下面一行，1 代表了在這個堆疊上，只有一個協程在執行。但其實在計算出數字1時，並不僅僅按堆疊去做區分，還依據了協程labels值，也就是 協程的堆疊和lebels標籤值 共同構成了一個key，而數字1就是在遍歷所有協程資訊時，對相同key進行累加計數得來的。
我們可以透過下面的方式為協程設定labels。
pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), pprof.Labels("name", "lanpangzi", "age", "18")))
透過上述程式碼，我可以為當前協程設定了兩個標籤值，分別是name和age，設定label值之後，再來看debug=1後的網頁輸出，可以發現 設定的labels出現了。
1 @ 0x104f86c60 0x104fb7358 0x105236368 0x104f867ec 0x104fba024 # labels: {"age":"18", "name":"lanpangzi"} # 0x104fb7357 time.Sleep+0x137 /Users/xiongchuanhong/goproject/src/go/src/runtime/time.go:193 # 0x105236367 main.main+0x437 /Users/xiongchuanhong/goproject/src/go/main/main.go:46 # 0x104f867eb runtime.main+0x25b /Users/xiongchuanhong/goproject/src/go/src/runtime/proc.go:255
而數字1之後，就是協程正在執行的函式堆疊資訊了。
使用二進位制檔案檢視
我們可以透過如下程式碼生成profile的二進位制檔案，在下述程式碼中，我生成了兩個協程，然後開啟對goroutine指標的採集，
package main
import (
"fmt"
"github.com/pkg/profile"
"time")
func main() {
go mockGo()
go mockGo()
p := profile.Start(profile.GoroutineProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook)
p.Stop()
}
func mockGo() {
time.Sleep(time.Second * 3)
fmt.Println("獲取鎖")
}
生成的goroutine二進位制檔案後，檢視goroutine 方式也和其他profile指標一致，這裡我直接放上透過web瀏覽器檢視的graph。 顯示的堆疊資訊為當前程式中協程正在執行的堆疊，可以看到main.mockGo 函式中有兩個協程在執行這個方法，main方法中一個協程在執行。
thread
http介面暴露的控制檯檢視
介紹完goroutine指標的輸出資訊後，再來看看threadcreate 執行緒建立指標的 輸出資訊。先來看下在控制檯中透過點選thread連結看到的輸出，
老規矩，先看位址列，debug=1代表 輸出的是文字可讀的資訊，threadcreate 就沒有debug=2的特別輸出了，debug=0時 同樣也會下載一個可供go tool pprof分析的二進位制檔案。
接著threadcreate pfofile表明了profile的型別。
total 12 代表了此時總共有12個執行緒被建立。
11 代表了在這個總共有11個執行緒是在這個堆疊的程式碼段上被建立的，注意這裡後面沒有堆疊內容，說明runtime在建立執行緒時，並沒有把此時的堆疊記錄下來，原因有可能是 這個執行緒是runtime自己使用的，堆疊沒有必要展示給使用者，所以乾脆不記錄了，具體原因這裡就不深入研究了。
上面輸出的內容可以看到在main方法裡面建立了一個執行緒，runtime.newm 方法內部，runtime會啟動一個系統執行緒。
使用二進位制檔案檢視
在程式碼中開始採集thread的資訊，生成二進位制檔案可以採用以下程式碼，和goroutine示例程式碼類似，不同的是改變採集的指標物件，改成了ThreadcreationProfile。
package main
import (
"fmt"
"github.com/pkg/profile"
"time")
func main() {
go mockGo()
go mockGo()
p := profile.Start(profile.ThreadcreationProfile,
profile.ProfilePath("profile"),
profile.NoShutdownHook)
p.Stop()
}
func mockGo() {
time.Sleep(time.Second * 3)
fmt.Println("獲取鎖")
}
生成的二進位制檔案透過 go tool pprof -http=:8083 ../profile/threadcreation.pprof 啟動瀏覽器視窗檢視其graph，如下是執行緒的graph，圖中的堆疊資訊是建立執行緒時的堆疊資訊。
自薦一波：
歡迎朋友們關注我的公眾號📢📢：【藍胖子的程式設計夢】!
歡迎點贊 👍、收藏 💙、關注 💡 三連支援一下～🎈🎈
我是藍胖子，下期見～🙇💻