gbd 分析core文件_Go 性能分析工具 pprof 入门
(給Go開發大全加星標)
來源：wudaijun
https://wudaijun.com/2018/04/go-pprof/
【導讀】pprof是golang用于性能分析的工具、可以生成圖形和文本報告。在實際項目中對高并發場景下的服務上線前必須經過pprof驗證，本文介紹了pprof的用法。
一. pprof 數據采樣
pprof 采樣數據主要有三種獲取方式:
runtime/pprof: 手動調用runtime.StartCPUProfile或者runtime.StopCPUProfile等 API來生成和寫入采樣文件，靈活性高
net/http/pprof: 通過 http 服務獲取Profile采樣文件，簡單易用，適用于對應用程序的整體監控。通過 runtime/pprof 實現
go test: 通過?go test -bench . -cpuprofile prof.cpu生成采樣文件 適用對函數進行針對性測試
1.1 net/http/pprof
在應用程序中導入import _ "net/http/pprof"，并啟動 http server即可:
// net/http/pprof 已經在 init()函數中通過 import 副作用完成默認 Handler 的注冊go func() { log.Println(http.ListenAndServe("localhost:6060", nil))}()之后可通過 http://localhost:6060/debug/pprof/CMD 獲取對應的采樣數據。支持的 CMD 有:
goroutine: 獲取程序當前所有 goroutine 的堆棧信息。
heap: 包含每個 goroutine 分配大小，分配堆棧等。每分配 runtime.MemProfileRate(默認為512K) 個字節進行一次數據采樣。
threadcreate: 獲取導致創建 OS 線程的 goroutine 堆棧
block: 獲取導致阻塞的 goroutine 堆棧(如 channel, mutex 等)，使用前需要先調用?runtime.SetBlockProfileRate
mutex: 獲取導致 mutex 爭用的 goroutine 堆棧，使用前需要先調用?runtime.SetMutexProfileFraction
以上五個 CMD 都通過runtime/pprof Profile 結構體統一管理，以 Lookup 提供統一查詢接口，有相似的返回值(goroutine 堆棧)，它們都支持一個 debug URL參數，默認為0，此時返回的采樣數據是不可人為解讀的函數地址列表，需要結合 pprof 工具才能還原函數名字。debug=1時，會將函數地址轉換為函數名，即脫離 pprof 在瀏覽器中直接查看。對 goroutine CMD來說，還支持 debug=2，此時將以 unrecovered panic 的格式打印堆棧，可讀性更高。如啟用net/http/pprof后，http://localhost:6060/debug/pprof/goroutine?debug=2?的響應格式為:
goroutine 18 [chan receive, 8 minutes]:ngs/core/glog.logWorker(0x18b548a, 0x4, 0x7fff5fbffb0e, 0x0, 0x3, 0xc4200e31a0, 0xc4203627c4) /Users/wudaijun/go/src/ngs/core/glog/worker.go:43 +0x19ccreated by ngs/core/glog.newLogger /Users/wudaijun/go/src/ngs/core/glog/glog.go:51 +0xe4goroutine 6 [syscall, 8 minutes]:os/signal.signal_recv(0x0) /usr/local/Cellar/go/1.9.1/libexec/src/runtime/sigqueue.go:131 +0xa7os/signal.loop() /usr/local/Cellar/go/1.9.1/libexec/src/os/signal/signal_unix.go:22 +0x22created by os/signal.init.0 /usr/local/Cellar/go/1.9.1/libexec/src/os/signal/signal_unix.go:28 +0x41goroutine 50 [select, 8 minutes]:context.propagateCancel.func1(0x1cfcee0, 0xc42017a1e0, 0x1cf3820, 0xc42005b480) /usr/local/Cellar/go/1.9.1/libexec/src/context/context.go:260 +0x113created by context.propagateCancel /usr/local/Cellar/go/1.9.1/libexec/src/context/context.go:259 +0x1da...以上幾種 Profile 可在?http://localhost:6060/debug/pprof/?中看到，除此之外，go pprof 的 CMD 還包括:
cmdline: 獲取程序的命令行啟動參數
profile: 獲取指定時間內(從請求時開始)的cpuprof，倒計時結束后自動返回。參數: seconds, 默認值為30。cpuprofile 每秒鐘采樣100次，收集當前運行的 goroutine 堆棧信息。
symbol: 用于將地址列表轉換為函數名列表，地址通過’+’分隔，如 URL/debug/pprof?0x18d067f+0x17933e7
trace: 對應用程序進行執行追蹤，參數: seconds, 默認值1s
這幾個 CMD 因為各種原因沒有整合到 Profile 結構中去，但就使用上而言，是沒有區別的，URL格式是一致的，因此可以看做一個整體，從各個角度對系統進行數據采樣和分析。
1.2 runtime/pprof
runtime/pprof提供各種相對底層的 API 用于生成采樣數據，一般應用程序更推薦使用net/http/pprof，runtime/pprof?的 API 參考runtime/pprof或 http pprof 實現。
1.3 go test
通常用net/http/pprof或runtime/pprof對應用進行整體分析，找出熱點后，再用go test進行基準測試，進一步確定熱點加以優化并對比測試。
# 生成 test 二進制文件， pprof 工具需要用到go test -c -o tmp.test # 執行基準測試 BenchAbc，并忽略任何單元測試，test flag前面需要加上'test.'前綴tmp.test -test.bench BenchAbc -test.run XXX test.cpuprofile cpu.prof # 與上面兩條命令等價，只不過沒有保留 test 二進制文件go test -bench BenchAbc -run XXX -cpuprofile=cpu.prof .go test可以直接加-cpuprofile?-mutexprofilefraction等參數實現prof數據的采樣和生成，更多相關參數參考?go test -h。
二. pprof 數據分析
雖然?net/http/pprof提供的數據分析可以通過設置參數后直接在瀏覽器查看，但 pprof 采樣數據主要是用于 pprof 工具的，特別針對 cpuprof, memprof, blockprof等來說，我們需要直觀地得到整個調用關系鏈以及每次調用的詳細信息，這是需要通過go tool pprof命令來分析:
go tool pprof [binary] [binary.prof]# 如果使用的 net/http/pprof 可以直接接 URLgo tool pprof http://localhost:6060/debug/pprof/profilego pprof 采樣數據是非常豐富的，大部分情況下我們只會用到 CPU 和 內存分析，因此這里介紹下 cpu, heap, block 和 mutex 四種 pprof 數據分析。
2.1 cpuprofile
以Profiling Go Programs中的示例代碼為例:
go build -o havlak1 havlak1.go ./havlak1 --cpuprofile=havlak1.prof# of loops: 76000 (including 1 artificial root node) go tool pprof havlak1 havlak1.profFile: havlak1Type: cpuTime: Apr 3, 2018 at 3:50pm (CST)Duration: 20.40s, Total samples = 23.30s (114.24%)Entering interactive mode (type "help" for commands, "o" for options)(pprof) top5Showing nodes accounting for 9.60s, 41.20% of 23.30s totalDropped 112 nodes (cum <= 0.12s)Showing top 5 nodes out of 90 flat flat% sum% cum cum% 2.59s 11.12% 11.12% 2.78s 11.93% runtime.mapaccess1_fast64 /usr/local/Cellar/go/1.9.1/libexec/src/runtime/hashmap_fast.go 2.26s 9.70% 20.82% 4.97s 21.33% runtime.scanobject /usr/local/Cellar/go/1.9.1/libexec/src/runtime/mgcmark.go 2.06s 8.84% 29.66% 13.79s 59.18% main.FindLoops /Users/wudaijun/Code/goprof/havlak/havlak1.go 1.39s 5.97% 35.62% 1.39s 5.97% runtime.heapBitsForObject /usr/local/Cellar/go/1.9.1/libexec/src/runtime/mbitmap.go 1.30s 5.58% 41.20% 4.14s 17.77% runtime.mapassign_fast64 /usr/local/Cellar/go/1.9.1/libexec/src/runtime/hashmap_fast.gotop5用于顯示消耗 CPU 前五的函數，每一行代表一個函數，每一列為一項指標:
flat: 采樣時，該函數正在運行的次數*采樣頻率(10ms)，即得到估算的函數運行”采樣時間”。這里不包括函數等待子函數返回。
flat%: flat / 總采樣時間值
sum%: 前面所有行的 flat% 的累加值，如第二行 sum% = 20.82% = 11.12% + 9.70%
cum: 采樣時，該函數出現在調用堆棧的采樣時間，包括函數等待子函數返回。因此 flat <= cum
cum%: cum / 總采樣時間值
PS: 老的pprof版本貌似顯示的是采樣次數，比如 flat 為采樣時該函數正在運行的次數，這個次數*采樣頻率即得到采樣時間。
go tool pprof?常用命令:
topN: 輸入 top 命令，默認顯示 flat 前10的函數調用，可使用 -cum 以 cum 排序
list Func: 顯示函數名以及每行代碼的采樣分析
web: 生成 svg 熱點圖片，可在瀏覽器中打開，可使用 web Func 來過濾指定函數相關調用樹
通過top5命令可以看到，mapaccess1_fast64函數占用的CPU 采樣時間最多，通過?web mapaccess1_fast64?命令打開調用圖譜，查看該函數調用關系，可以看到主要在DFS 和 FindLoops 中調用的，然后再通過?list DFS查看函數代碼和關鍵調用，得到 map 結構是瓶頸點，嘗試轉換為 slice 優化，整個過程參考Profiling Go Programs。總的思路就是通過top?和web?找出關鍵函數，再通過list Func?查看函數代碼，找到關鍵代碼行并確認優化方案(輔以 go test Benchmark)。
2.2 memprofile
go build -o havlak3 havlak3.go ./havlak3 --memprofile=havlak3.mprof go tool pprof havlak3 havlak3.mprofFile: havlak3Type: inuse_spaceTime: Apr 3, 2018 at 3:44pm (CST)Entering interactive mode (type "help" for commands, "o" for options)(pprof) topShowing nodes accounting for 57.39MB, 100% of 57.39MB total flat flat% sum% cum cum% 39.60MB 69.00% 69.00% 39.60MB 69.00% main.FindLoops /Users/wudaijun/Code/goprof/havlak/havlak3.go 11.29MB 19.67% 88.67% 11.29MB 19.67% main.(*CFG).CreateNode /Users/wudaijun/Code/goprof/havlak/havlak3.go 6.50MB 11.33% 100% 17.79MB 31.00% main.NewBasicBlockEdge /Users/wudaijun/Code/goprof/havlak/havlak3.go 0 0% 100% 39.60MB 69.00% main.FindHavlakLoops /Users/wudaijun/Code/goprof/havlak/havlak3.go 0 0% 100% 17.79MB 31.00% main.buildBaseLoop /Users/wudaijun/Code/goprof/havlak/havlak3.gomemprofile 也就是 heap 采樣數據，go tool pprof 默認顯示的是使用的內存的大小，如果想要顯示使用的堆對象的個數，則通過go tool pprof --inuse_objects havlak3 havlak3.mprof，其它參數還有--alloc_objects和--alloc_space，分別是分配的堆內存大小和對象個數。在本例中，FindLoops 函數分配了39.60M 堆內存，占到69%，同樣，接下來是通過list FindLoops對函數代碼進行 review，找出關鍵數據結構，進行優化。
2.3 blockprofile
var mutex sync.Mutexfunc main() { // rate = 1 時, 統計所有的 block event, // rate <=0 時，則關閉block profiling // 參考 https://github.com/golang/go/blob/release-branch.go1.9/src/runtime/mprof.go#L397 runtime.SetBlockProfileRate(1 * 1000 * 1000) var wg sync.WaitGroup // rate > 1 時，為 ns 數，阻塞時間t>rate的event 一定會被統計 //小于rate則有t/rate 的幾率被統計 wg.Add(1) mutex.Lock() go worker(&wg) time.Sleep(2*time.Millisecond) mutex.Unlock() wg.Wait() writeProfTo("block", "block.bprof")}func worker(wg *sync.WaitGroup) { defer wg.Done() mutex.Lock() time.Sleep(1*time.Millisecond) mutex.Unlock()}func writeProfTo(name, fn string) { p := pprof.Lookup(name) if p == nil { fmt.Errorf("%s prof not found", name) return } f, err := os.Create(fn) if err != nil { fmt.Errorf("%v", err.Error()) return } defer f.Close() err = p.WriteTo(f, 0) if err != nil { fmt.Errorf("%v", err.Error()) return }}運行程序并 pprof:
go build -o Temp tmp.gogo tool pprof Temp block.bprof(pprof) topShowing nodes accounting for 3.37ms, 100% of 3.37ms total flat flat% sum% cum cum% 2.04ms 60.52% 60.52% 2.04ms 60.52% sync.(*Mutex).Lock /usr/local/Cellar/go/1.9.1/libexec/src/sync/mutex.go 1.33ms 39.48% 100% 1.33ms 39.48% sync.(*WaitGroup).Wait /usr/local/Cellar/go/1.9.1/libexec/src/sync/waitgroup.go 0 0% 100% 1.33ms 39.48% main.main /Users/wudaijun/go/src/ngs/test/tmp/tmp.go 0 0% 100% 2.04ms 60.52% main.worker /Users/wudaijun/go/src/ngs/test/tmp/tmp.go 0 0% 100% 3.37ms 100% runtime.goexit /usr/local/Cellar/go/1.9.1/libexec/src/runtime/asm_amd64.s 0 0% 100% 1.33ms 39.48% runtime.main /usr/local/Cellar/go/1.9.1/libexec/src/runtime/proc.go可以看到程序在 mutex.Lock 上阻塞了2.04ms(worker goroutine)， 在 WaitGroup.Wait 上等待了1.33ms(main goroutine)，從更上層來看，在 main 函數中一共阻塞了2.04ms，worker函數中阻塞了1.33ms(cum 列)，通過?web命令生成 svg 圖片在瀏覽器查看:
可以很直觀地看到整個阻塞調用鏈，對于耗時較多的阻塞調用加以優化。
2.4 mutexprofile
仍然用2.3中的代碼，只需要改兩個地方，將?runtime.SetBlockProfileRate(1 * 1000 * 1000)?改為:
// 當 rate = 0 時，關閉 mutex prof (默認值)// 當 rate = 1 時，表示記錄所有的 mutex event// 當 rate > 1 時，記錄 1/rate 的 mutex event(隨機)runtime.SetMutexProfileFraction(1)再將writeProfTo("block", "block.bprof")改為writeProfTo("mutex", "mutex.mprof")即可，編譯運行，并打開 pprof 工具:
go?tool?pprof?bin/Temp?mutex.mprof(pprof) topShowing nodes accounting for 2.55ms, 100% of 2.55ms total flat flat% sum% cum cum% 2.55ms 100% 100% 2.55ms 100% sync.(*Mutex).Unlock /usr/local/Cellar/go/1.9.1/libexec/src/sync/mutex.go 0 0% 100% 2.55ms 100% main.main /Users/wudaijun/go/src/ngs/test/tmp/tmp.go 0 0% 100% 2.55ms 100% runtime.goexit /usr/local/Cellar/go/1.9.1/libexec/src/runtime/asm_amd64.s 0 0% 100% 2.55ms 100% runtime.main /usr/local/Cellar/go/1.9.1/libexec/src/runtime/proc.go查看 svg 圖:
三. 實踐 Tips
以下是一些從其它項目借鑒或者自己總結的實踐經驗，它們只是建議，而不是準則，實際項目中應該以性能分析數據來作為優化的參考，避免過早優化。
對頻繁分配的小對象，使用?sync.Pool?對象池避免分配
自動化的 DeepCopy 是非常耗時的，其中涉及到反射，內存分配，容器(如 map)擴展等，大概比手動拷貝慢一個數量級
用 atomic.Load/StoreXXX，atomic.Value, sync.Map 等代替 Mutex。(優先級遞減)
使用高效的第三方庫，如用fasthttp替代 net/http
在開發環境加上-race編譯選項進行競態檢查
在開發環境開啟 net/http/pprof，方便實時 pprof
將所有外部IO(網絡IO，磁盤IO)做成異步
1、RedHat容器術語實用導論
2、圖解 Goroutine 與搶占機制
3、淺析 k8s 容器運行時演進
如果覺得本文不錯，歡迎轉發推薦給更多人。
分享、點贊和在看
支持我們分享更多好文章，謝謝！
總結
以上是生活随笔為你收集整理的gbd 分析core文件_Go 性能分析工具 pprof 入门的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： el-popover可以设高度_家用餐厅
- 下一篇： elasticsearch java对象