golang pprof監控系列(2) —— memory,block,mutex 使用
大家好,我是藍胖子。
profile的中文被翻譯輪廓,對於計算機程式而言,拋開業務邏輯不談,它的輪廓是是啥呢?不就是cpu,記憶體,各種阻塞開銷,執行緒,協程概況 這些執行指標或環境。golang語言自帶了工具庫來幫助我們描述,探測,分析這些指標或者環境資訊,讓我們來學習它。
在上一篇golang pprof 監控系列(1) —— go trace 統計原理與使用 裡我講解了下golang trace 工具的統計原理,它能夠做到對程式執行中的各種事件進行耗時統計。而今天要將的memory,block,mutex 統計的原理與之不同,這是一個在一段時間內進行取樣得到的累加值。
還記得之前用go trace 生成的網頁圖嗎?
裡面是不是也有 3個名字帶有blocking的 profile的輪廓圖,分別是Network blocking profile,Synchronization blocking profile,Syscall blocking profile ,而它與今天要說的block 統計有沒有什麼關聯? 先說下結論,block統計的內容有重合,但是不多,並且統計資料來源是不同的。
Synchronization blocking profile 和 今天的block統計 是一致的
然後之所以 memory,block,mutex 把這3類資料放在一起講,是因為他們統計的原理是很類似的,好的,在瞭解統計原理之前,先簡單看下如何使用golang提供的工具對這些資料型別進行分析。
如何使用
在看使用程式碼前,還需要了解清楚對這3種型別的指標對哪些資料進行統計。
兩種方式都比較常見,首先來看下http 介面暴露這些效能指標的方式。
http 介面暴露的方式
package main
import (
"log"
"net/http"
_ "net/http/pprof"
)
func main() {
log.Println(http.ListenAndServe(":6060", nil))
}
使用方式相當容易,直接程式碼引入net/http/pprof ,便在預設的http處理器上註冊上了相關路由,引入包的目的就是為了呼叫對應包的init方法註冊路由。下面就是引用包的init方法。
// src/net/http/pprof/pprof.go:80
func init() {
http.HandleFunc("/debug/pprof/", Index)
http.HandleFunc("/debug/pprof/cmdline", Cmdline)
http.HandleFunc("/debug/pprof/profile", Profile)
http.HandleFunc("/debug/pprof/symbol", Symbol)
http.HandleFunc("/debug/pprof/trace", Trace)
}
接下來訪問路由 http://127.0.0.1:6060/debug/pprof/ 便能看到下面網頁內容了。
標註為紅色的部分就是今天要講的內容,點選它們的連結會跳到對應的網頁看到統計資訊。我們挨個來看下。
allocs ,heap
這兩個值都是記錄程式記憶體分配的情況。
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
在 go1.17.12 這兩者的資訊輸出其實是一樣的,實現的程式碼也基本一致,僅僅是在名稱上做了區分
按pprof http伺服器啟動網頁上的顯示來說,allocs 是過去記憶體的取樣,heap 是存活物件的採用記錄,然而實際上在程式碼實現上兩者是一致的。並沒有做區分。
下面來講下網頁輸出內容的含義
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暫存器的值。再往後就是具體的棧函式名資訊了。
block
接下來看看block會對哪些行為產生記錄,每次程式鎖阻塞發生時,select 阻塞,channel通道阻塞,wait group 產生阻塞時就會記錄一次阻塞行為。對阻塞行為的記錄其實是和trace 的Synchronization blocking profile 是一致的,但是和其他兩個blocking profile 不一樣。
要得到block的輸出資訊首先要開啟下記錄block的開關.
// 1 代表 全部取樣,0 代表不進行採用, 大於1則是設定納秒的取樣率
runtime.SetBlockProfileRate(1)
這個取樣率是怎樣計算的,我們來看下具體程式碼。
// src/runtime/mprof.go:409
func blocksampled(cycles, rate int64) bool {
if rate <= 0 || (rate > cycles && int64(fastrand())%rate > cycles) {
return false
}
return true
}
cycles你可以把它理解成也是一個納秒級的事件,rate就是我們設定的納秒時間,如果 cycles大於等於rate則直接記錄block行為,如果cycles小於rate的話,則需要fastrand函式乘以設定的納秒時間rate 來決定是否取樣了。
然後回過頭來看看網頁的輸出資訊
--- 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 是每秒鐘的週期數,用它來表示時間也是為了更精確,其實你可以發現在我的機器上每秒是10的9次方個週期,換算成納秒就是1ns一個週期時間了。
接著的180001216583 是阻塞的週期數,其實週期就是cputicks,那麼180001216583除以 cycles/second 1000000000得到的就是阻塞的秒數了。
接著 1代表阻塞的次數。
無論是阻塞週期時長還是次數,都是一個累加值,即在相同的地方阻塞會導致這個值變大,並且次數會增加。剩下的部分就是函式堆疊資訊了。
mutex
接著來看mutex相關內容,block也在鎖阻塞時記錄阻塞行為,那麼mutex與它有什麼不同?
直接說下結論,mutex是在解鎖unlock時才會記錄一次阻塞行為,而block在記錄mutex鎖阻塞資訊時,是在開始執行lock呼叫的時候記錄的。
要想記錄mutex資訊,和block類似,也需要開啟mutex取樣開關。
// 0 代表不進行採用, 1則全部採用,大於1則是一個隨機採用
runtime.SetMutexProfileFraction(1)
來看看取樣的細節程式碼,程式碼版本go1.17.12
if rate > 0 && int64(fastrand())%rate == 0 {
saveblockevent(cycles, rate, skip+1, mutexProfile)
}
可以看到fastrand() 與rate取模等於0才會去取樣,rate如果設定成1,則任何數與整數與1取模都會得到0,所以設定為1為完全採用,大於1比如rate設定為2,則要求fastrand必須是2的倍數才能被取樣。
接著來看下網頁的輸出資訊。
--- 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為解鎖的次數。然後是解鎖的堆疊資訊。
介紹完利用http服務檢視pprof效能指標的方式來看看,如何用程式碼來生成這些pprof的二進位制或者文字檔案。
程式碼生成profile檔案的方式
首先來看看如何對記憶體資訊生成pprof檔案。
os.Remove("heap.out")
f, _ := os.Create("heap.out")
defer f.Close()
err := pprof.Lookup("heap").WriteTo(f, 1)
if err != nil {
log.Fatal(err)
}
lookup 傳遞的heap引數也可以改成allocs,不過輸出的內容是一致的。
WriteTo 第二個引數叫做debug,傳1代表 會生成可讀的文字檔案,就和http服務看heap allocs的網頁一樣的。傳0代表是要生成一個二進位制檔案。生成的二進位制檔案可以用go tool pprof pprof檔名 去分析,關於go tool pprof 工具的使用網上有相當多的資料,這裡就不再展開了。
然後來看看如何生成block的pprof檔案。
runtime.SetBlockProfileRate(1)
os.Remove("block.out")
f, _ := os.Create("block.out")
defer f.Close()
err := pprof.Lookup("block").WriteTo(f, 1)
if err != nil {
log.Fatal(err)
}
pprof.Lookup方法傳遞block即可生成檔案了,使用方式和生成記憶體分析檔案一致,,傳1代表 會生成可讀的文字檔案,就和http服務看block的網頁一樣的。傳0代表是要生成一個二進位制檔案。生成的二進位制檔案可以用go tool pprof pprof檔名 去分析。
最後看看mutex,和前面兩者基本一致僅僅是Lookup傳遞的引數有變化,這裡就不再敘述了。
runtime.SetMutexProfileFraction(1)
os.Remove("mutex.out")
f, _ := os.Create("mutex.out")
defer f.Close()
err := pprof.Lookup("mutex").WriteTo(f, 1)
if err != nil {
log.Fatal(err)
}
總結
經過上述的講解,應該是能夠明白相關的指標究竟是採集了哪些內容並且何時採集的了,而go tool pprof 工具的使用不是此文的重點,所以我直接省略掉了,也是沒想到即使省略了,還是內容有那麼多,那就把這部分的統計原理留到下一篇文章了,下一篇,memory,block,mutex 統計的原理介紹。