萬字長文講解 Golang pprof 的使用
大家好，我是藍胖子，說到golang的性能分析，不得不提的就是其自身擁有的pprof，它提供了從cpu，內(nèi)存，阻塞情況，協(xié)程，線程，乃至程序運行軌跡trace的分析，可以說相當強大了。
今天我將會用較長的篇幅闡述 應該如何使用pprof工具來 對cpu，內(nèi)存，阻塞情況，協(xié)程，線程 這幾個維度去進行分析。
其實總結出來Golang pprof的使用方式，可以用下面的思維導圖來表示。
圖片
要么在程序中通過http接口的方式暴露相應的pprof的采集控制界面，要么就是在程序中通過代碼開啟對應指標的采集樣本功能，采集一段時間的樣本后生成二進制文件，最后通過 go tool pprof 命令去對樣本的數(shù)據(jù)進行分析。
分析的方式也有兩種，
- 通過命令行開啟一個交互終端
- 通過瀏覽器將二進制文件的信息展示出來
我們可以通過下述的代碼通過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/ 便會出現(xiàn)各種維度指標，可以點擊進去查看具體的指標信息。如下所示：
圖片
接下來我們來分析下各個指標在 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：函數(shù)自身的運行耗時（排除了子函數(shù)的調用耗時）
flat%：flat運行耗時占用總的采集樣本的時間和的比例，這里所有節(jié)點運行的flat時間和為200ms。
sum%：命令行返回結果中函數(shù)自身和其之上的函數(shù)運行的flat時間占所有采集樣本時間總和的比例。
cum：當前函數(shù)和其子函數(shù)的調用耗時總的運行時間
cum%：cum耗時占總的采集樣本的時間和的比例。
分析中可以看出主要是打印日志占用了比較大的cpu。
在命令行中可以輸入svg，來輸出cpu性能剖析的profile 圖。
(pprof) svg
Generating report in profile001.svg
圖片
圖中顯示了函數(shù)的調用關系，函數(shù)框中顯示了函數(shù)自身的運行時長flat和其自身及其子函數(shù)運行時長cum，箭頭上的時間則是其子函數(shù)的cum運行時長，時間越大，箭頭越粗。
將二進制文件信息輸出到瀏覽器上
可以通過如下命令來啟動瀏覽器查看cpu使用情況，
go tool pprof -http=:8082 cpuprofile/cpu.pprof火焰圖分析性能問題
通過web界面，我們除了按剛才的top和調用耗時圖像外，甚至還能通過火焰圖的方式，來查看cpu調用耗時，火焰圖上，函數(shù)的調用順序是從上往下，函數(shù)占用cpu越長，那么在火焰圖上的區(qū)塊就會越大。 火焰圖中顯示的是cum值。
圖片
peek
圖片
除了像top那樣輸出函數(shù)的耗時情況，還會輸出調用函數(shù)和被調用函數(shù)，調用順序從上到下。
source
Pasted image 20240304175712.png
在web界面可以通過source視圖去查看函數(shù)節(jié)點的耗時以及它的子調用函數(shù)中耗時的地方，第一欄時間是flat耗時，第二欄時間是cum耗時。 耗時百分比是cum耗時占樣本總和的百分比。
內(nèi)存
http接口暴露的控制臺查看
通過點擊heap或者allocs 鏈接可以查看內(nèi)存的分配情況，它們的輸出都是一致的。
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下面來講下網(wǎng)頁輸出內(nèi)容的含義：
heap profile: 7: 5536 [110: 2178080] @ heap/1048576輸出的第一行含義分別是:
7 代表 當前活躍的對象個數(shù)
5536 代表 當前活躍對象占用的字節(jié)數(shù)
110 代表 所有(包含歷史的對象)對象個數(shù)
2178080 代表 所有對象(包含歷史的對象)占用的對象字節(jié)數(shù)
1048576 控制了內(nèi)存采樣的頻率，1048576 是兩倍的內(nèi)存采樣頻率的大小，默認采樣頻率是512kb 即平均每512kb就會采樣一次，注意這個值512kb不是絕對的達到512kb就會進行采樣，而是從一段時間內(nèi)的采樣來看的一個平均值。
接下來就是函數(shù)調用堆棧信息，來看第一行。
2: 2304 [2: 2304] @ 0x100d7e0ec 0x100d7ea78 0x100d7f260 0x100d7f78c 0x100d811cc 0x100d817d4 0x100d7d6dc 0x100d7d5e4 0x100daba20從左往右看：
2 代表 在該函數(shù)棧上當前活躍的對象個數(shù)
2304 代表 在該函數(shù)棧上當前活躍的對象所占用的字節(jié)數(shù)
方括號內(nèi)的2 代表 在該函數(shù)棧上所有(包含歷史的對象)對象個數(shù)
方括號內(nèi)的2304 代表 在該函數(shù)棧上所有(包含歷史的對象)對象所占用的字節(jié)數(shù)
然后是棧上pc寄存器的值。再往后就是具體的棧函數(shù)名信息了。
通過二進制文件查看
我們可以使用如下代碼生成一個關于內(nèi)存使用情況的二進制profile文件，下述代碼中我用 allocMem 函數(shù)不斷對一個字節(jié)數(shù)組進行append操作來模擬內(nèi)存不斷增大的情況。
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瀏覽器去進行查看，所以啟動終端的方式我這里就暫時略去了， 講講不同點， 針對于內(nèi)存，pprof在web 瀏覽器界面提供了幾個維度去分析。
inuse_space: 正在使用，尚未釋放的空間
inuse_object: 正在使用，尚未釋放的對象
alloc_space: 所有分配的空間，包含已釋放的
alloc_objects: 所有分配的對象，包含已釋放的
拿inuse_object舉例，性能剖析圖是這樣的，箭頭顯示了正在使用的對象個數(shù)，其中 main.allocMem函數(shù)自身有一個4MB多的對象，其子函數(shù)有4個對象。
圖片
我們可以根據(jù)source 選項也能得到同樣的分析結果。
圖片
block
block可用于分析程序鎖mutex，select ，channel通道, wait group 的阻塞行為。
但是block通常是關閉的，需要通過下面代碼進行開啟。
runtime.SetBlockProfileRate(1)其中,SetBlockProfileRate 的參數(shù)名為rate，rate不同，對block事件的采樣頻率不同。
- 1 代表 始終對阻塞事件進行采樣
- <= 0 代表關閉阻塞事件的采樣
- 除了上述兩種情況，SetBlockProfileRate 的參數(shù)傳遞的將會是一個納秒值。
如果阻塞的時間大于了rate值則直接進行采樣，如果阻塞的時間小于rate，那么阻塞事件將會有(阻塞時間)/rate 的可能性被采集到。
?????? 注意下block事件的記錄時機為獲取鎖資源或者channel 資源時，進行記錄，也就是發(fā)生在lock函數(shù)中。
http接口暴露的控制臺查看
通過點擊http接口暴露的pprof控制的block鏈接，可以查看程序中block的情況，瀏覽器輸出如下：
--- contention:
cycles/secnotallow=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:33contention 是為這個profile文本信息取的名字，總之中文翻譯是爭用。
cycles/second 是cpu時鐘每秒鐘的周期數(shù)，用它來表示時間也是為了更精確，其實你可以發(fā)現(xiàn)在我的機器上每秒是10的9次方個周期，換算成納秒就是1ns一個周期時間了。
接著的180001216583 是阻塞的周期數(shù)，其實周期就是cputicks，那么180001216583除以 cycles/second 即1000000000得到的就是阻塞的秒數(shù)了。
接著 1 代表阻塞的次數(shù)。
無論是阻塞周期時長還是次數(shù)，都是一個累加值，即在相同的地方阻塞會導致這個值變大，并且次數(shù)會增加。剩下的部分就是函數(shù)堆棧信息了。
使用二進制文件查看
可以通過如下代碼生成block的二進制文件，通過在主協(xié)程中使用lock方法后，不釋放鎖資源，啟動子協(xié)程，讓子協(xié)程同樣使用lock方法模擬系統(tǒng)阻塞的情況。
import (
"fmt"
"github.com/pkg/profile"
"runtime"
"sync"
"time")
/*
*
每次程序鎖阻塞發(fā)生時，select 阻塞，channel通道阻塞,
wait group 產(chǎn)生阻塞時就會記錄一次阻塞行為
*/
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.pprofblock提供了兩個維度去觀察阻塞事件 ，contention 發(fā)生阻塞的事件個數(shù)，delay 發(fā)生阻塞的時間。
contention 生成的profile圖如下，可以看到發(fā)生阻塞的函數(shù)是main.mockBlock ，其自身包括其調用子函數(shù)的阻塞次數(shù)是2次。
圖片
delay生成的profile 圖如下所示，main.mockBlock其自身包括其調用子函數(shù)的阻塞時間是4s。
圖片
?????? 無論是阻塞次數(shù)還是阻塞時間，如果同一個函數(shù)發(fā)生了阻塞，那么次數(shù)和阻塞時間都會累加上去。
使用 阻塞時間/阻塞次數(shù) 能得到平均每次阻塞多長時間。
mutex
mutex 記錄的是持有鎖的時間，注意下它和block的區(qū)別，block記錄的是在獲取鎖之前阻塞的時間。并且block還可以記錄channel。
mutex 的采集默認情況下也是關閉的，需要用以下代碼進行開啟。
runtime.SetMutexProfileFraction(1)其中,SetMutexProfileFraction 的參數(shù)名為rate，rate不同，對block事件的采樣頻率不同。
- 1 代表 始終對持有鎖事件進行采樣
- = 0 代表關閉阻塞事件的采樣
- < 0 將會把當前的rate值讀取出來
- > 1 將會有1/rate 的持有鎖事件被采集
http接口暴露的控制臺查看
通過點擊http接口暴露的pprof控制的mutex鏈接，可以查看程序中鎖持有的的情況，瀏覽器輸出如下：
--- mutex:
cycles/secnotallow=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周期數(shù)計時，但是多了一個sampling period ，這個就是我們設置的采用頻率。
接下來的數(shù)據(jù)都和block類似，180001727833就是鎖持有的周期， 1為解鎖的次數(shù)。然后是解鎖的堆棧信息。
使用二進制文件查看
我們可以通過如下代碼生成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 發(fā)生持有鎖的事件個數(shù)，delay 持有鎖的時間。
以下是contention 維度的圖，可以看到在main方法中進行中持有了一次鎖，在mockBlock方法中也持有了一次鎖。
圖片
通過delay 維度可以發(fā)現(xiàn)main方法以及其子調用函數(shù)，持有鎖的時間一共是2s。
圖片
goroutine
http接口暴露的控制臺查看
點擊控制界面的goroutine鏈接，我們會看到在程序中goroutine正在執(zhí)行的函數(shù)堆棧信息，界面如下：
圖片
首先地址欄 /debug/pprof/goroutine?debug= 1 代表這是在訪問goroutine指標信息，debug =1 代表訪問的內(nèi)容將會以文本可讀的形式展現(xiàn)出來。 debug=0 則是會下載一個goroutine指標信息的二進制文件。 debug = 2 將會把當前所有協(xié)程的堆棧信息以文本可讀形式展示在網(wǎng)頁上。如下圖所示:
圖片
debug =2 時的 如上圖所示，41代表協(xié)程的id，方括號內(nèi)running代表了協(xié)程的狀態(tài)是運行中，接著就是該協(xié)程此時的堆棧信息了。
讓我們再回到debug = 1的分析上面去，剛才分析完了地址欄里的debug參數(shù)，接著，我們看輸出的第一行。
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個協(xié)程。
接著是下面一行，1 代表了在這個堆棧上，只有一個協(xié)程在執(zhí)行。但其實在計算出數(shù)字1時，并不僅僅按堆棧去做區(qū)分，還依據(jù)了協(xié)程labels值，也就是 協(xié)程的堆棧和lebels標簽值 共同構成了一個key，而數(shù)字1就是在遍歷所有協(xié)程信息時，對相同key進行累加計數(shù)得來的。
我們可以通過下面的方式為協(xié)程設置labels。
pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), pprof.Labels("name", "lanpangzi", "age", "18")))通過上述代碼，我可以為當前協(xié)程設置了兩個標簽值，分別是name和age，設置label值之后，再來看debug=1后的網(wǎng)頁輸出，可以發(fā)現(xiàn) 設置的labels出現(xiàn)了。
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而數(shù)字1之后，就是協(xié)程正在執(zhí)行的函數(shù)堆棧信息了。
使用二進制文件查看
我們可以通過如下代碼生成profile的二進制文件，在下述代碼中，我生成了兩個協(xié)程，然后開啟對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。 顯示的堆棧信息為當前程序中協(xié)程正在執(zhí)行的堆棧，可以看到main.mockGo 函數(shù)中有兩個協(xié)程在執(zhí)行這個方法，main方法中一個協(xié)程在執(zhí)行。
圖片
thread
http接口暴露的控制臺查看
介紹完goroutine指標的輸出信息后，再來看看threadcreate 線程創(chuàng)建指標的 輸出信息。先來看下在控制臺中通過點擊thread鏈接看到的輸出。
圖片
老規(guī)矩，先看地址欄，debug=1代表 輸出的是文本可讀的信息，threadcreate 就沒有debug=2的特別輸出了，debug=0時 同樣也會下載一個可供go tool pprof分析的二進制文件。
接著threadcreate pfofile表明了profile的類型。
total 12 代表了此時總共有12個線程被創(chuàng)建。
11 代表了在這個總共有11個線程是在這個堆棧的代碼段上被創(chuàng)建的，注意這里后面沒有堆棧內(nèi)容，說明runtime在創(chuàng)建線程時，并沒有把此時的堆棧記錄下來，原因有可能是 這個線程是runtime自己使用的，堆棧沒有必要展示給用戶，所以干脆不記錄了，具體原因這里就不深入研究了。
上面輸出的內(nèi)容可以看到在main方法里面創(chuàng)建了一個線程，runtime.newm 方法內(nèi)部，runtime會啟動一個系統(tǒng)線程。
使用二進制文件查看
在代碼中開始采集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，圖中的堆棧信息是創(chuàng)建線程時的堆棧信息。
圖片
