例子 gist 來自以前的 Trie 的實現, Ruby vs Go.ruby

main 函數加上了下面幾行:網絡

1 2 3 4 5 6 
import "runtime/pprof" // ... cpuProfile, _ := os.Create("cpu_profile") pprof.StartCPUProfile(cpuProfile) defer pprof.StopCPUProfile() // ...

這裏 os.Create("cpu_profile") 指定生成的數據文件, 而後 pprof.StartCPUProfile 看名字就知道是開始對 CPU 的使用進行監控. 有開始就有結束, 通常直接跟着 defer pprof.StopCPUProfile() 省的後面忘了. 編譯執行一次之後會在目錄下生成監控數據並記錄到 cpu_profile. 接着就可使用 pprof 來解讀分析這些監控生成的數據.

When CPU profiling is enabled, the Go program stops about 100 times per second and records a sample consisting of the program counters on the currently executing goroutine’s stack.

CPU Profiling

1 2 3 4 5 6 
$ go tool pprof cpu_profile Type: cpu Time: Jan 22, 2019 at 3:02pm (CST) Duration: 518.52ms, Total samples = 570ms (109.93%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)

由於是在多核環境, 因此, 取樣時間(Total samples) 佔比大於 100% 也屬於正常的. 交互操做模式提供了一大票的命令, 執行一下 help 就有相應的文檔了. 好比輸出報告到各類格式(pdf, png, gif), 方塊越大個表示消耗越大.

又或者列出 CPU 佔比最高的一些(默認十個)運行結點的 top 命令, 也能夠加上須要的結點數好比 top15

 1  2  3  4  5  6  7  8  9 10 11 12 13 14 
(pprof) top Showing nodes accounting for 480ms, 84.21% of 570ms total Showing top 10 nodes out of 67 flat flat% sum% cum cum% 200ms 35.09% 35.09% 210ms 36.84% main.NewNode (inline) 70ms 12.28% 47.37% 170ms 29.82% runtime.scanobject 60ms 10.53% 57.89% 70ms 12.28% runtime.greyobject 30ms 5.26% 63.16% 30ms 5.26% runtime.memclrNoHeapPointers 30ms 5.26% 68.42% 30ms 5.26% runtime.memmove 20ms 3.51% 71.93% 250ms 43.86% main.(*Node).insert 20ms 3.51% 75.44% 20ms 3.51% runtime.findObject 20ms 3.51% 78.95% 230ms 40.35% runtime.gcDrain 20ms 3.51% 82.46% 20ms 3.51% runtime.pthread_cond_wait 10ms 1.75% 84.21% 10ms 1.75% runtime.(*gcWork).tryGetFast (inline)
  • flat: 是指該函數執行耗時, 程序總耗時 570ms, main.NewNode 的 200ms 佔了 35.09%
  • sum: 當前函數與排在它上面的其餘函數的 flat 佔比總和, 好比 35.09% + 12.28% = 47.37%
  • cum: 是指該函數加上在該函數調用以前累計的總耗時, 這個看圖片格式的話會更清晰一些.

能夠看到, 這裏最耗 CPU 時間的是 main.NewNode 這個操做.

除此外還有 list 命令能夠根據匹配的參數列出指定的函數相關數據, 好比:

Memory Profiling

1 2 3 
// ... memProfile, _ := os.Create("mem_profile") pprof.WriteHeapProfile(memProfile)

相似 CPU 的監控, 要監控內存的分配回收使用狀況, 只要調用 pprof.WriteHeapProfile(memProfile)

而後是跟上面同樣的生成圖片:

Type: inuse_space 是監控內存的默認選項, 還能夠選 -alloc_space, -inuse_objects, -alloc_objects

inuse_space 是正在使用的內存大小, alloc_space是從頭至尾一共分配了的內存大小(包括已經回收了的), 後綴爲 _objects 的是相應的對象數

net/http/pprof

對於 http 服務的監控有一些些的不一樣, 不過 Go 已經對 pprof 作了一些封裝在 net/http/pprof

例子 gist 來自從 net/http 入門到 Gin 源碼梳理

引入多一行 _ "net/http/pprof", 啓用服務之後就能夠在路徑 /debug/pprof/ 看到相應的監控數據. 相似下面(已經很貼心的把各自的描述信息寫在下邊了):

用 wrk (brew install wrk) 模擬測試

wrk -c 200 -t 4 -d 3m http://localhost:8080/hello

仍是沒有前面的那些可視化圖形 UI 直觀, 不過能夠經過 http://localhost:8080/debug/pprof/profile (其餘幾個指標也差很少, heap, alloc…)生成一個相似前面的 CPU profile 文件監控 30s 內的數據. 而後就能夠用 go tool pprof來解讀了.

 1  2  3  4  5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 
Type: cpu Time: Jan 22, 2019 at 4:22pm (CST) Duration: 30.13s, Total samples = 1.62mins (321.66%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 93.78s, 96.76% of 96.92s total Dropped 270 nodes (cum <= 0.48s) Showing top 10 nodes out of 52 flat flat% sum% cum cum% 81.42s 84.01% 84.01% 81.45s 84.04% syscall.Syscall 3.45s 3.56% 87.57% 3.45s 3.56% runtime.kevent 2.31s 2.38% 89.95% 2.31s 2.38% runtime.pthread_cond_wait 2.06s 2.13% 92.08% 2.07s 2.14% runtime.usleep 1.93s 1.99% 94.07% 1.93s 1.99% runtime.pthread_cond_signal 1.10s 1.13% 95.20% 1.10s 1.13% runtime.freedefer 0.85s 0.88% 96.08% 0.87s 0.9% runtime.nanotime 0.59s 0.61% 96.69% 4.07s 4.20% runtime.netpoll 0.04s 0.041% 96.73% 0.67s 0.69% runtime.newproc1 0.03s 0.031% 96.76% 44.18s 45.58% net/http.(*conn).readRequest (pprof) Type: alloc_space Time: Jan 22, 2019 at 4:26pm (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 21.91GB, 99.82% of 21.95GB total Dropped 66 nodes (cum <= 0.11GB) Showing top 10 nodes out of 16 flat flat% sum% cum cum% 6.72GB 30.61% 30.61% 6.72GB 30.62% net/textproto.(*Reader).ReadMIMEHeader 5.97GB 27.18% 57.80% 20.54GB 93.60% net/http.(*conn).readRequest 4GB 18.21% 76.01% 13.23GB 60.30% net/http.readRequest 2.01GB 9.16% 85.17% 2.01GB 9.16% net/url.parse 1.25GB 5.71% 90.88% 1.25GB 5.71% net.(*conn).Read 1.22GB 5.54% 96.42% 1.22GB 5.55% context.WithCancel 0.49GB 2.25% 98.68% 0.49GB 2.25% net/textproto.(*Reader).ReadLine 0.13GB 0.58% 99.25% 0.13GB 0.58% main.main.func1 0.12GB 0.56% 99.82% 0.12GB 0.56% bufio.NewWriterSize (inline) 0 0% 99.82% 0.13GB 0.59% net/http.(*ServeMux).ServeHTTP (pprof)

gin pprof

import _ "net/http/pprof" 其實是爲了執行包 net/http/pprof 中的 init 函數.

1 2 3 4 5 6 7 8 
// pprof.go 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) }

所以, Gin 項目要使用 pprof 的話能夠參考這裏

Flame Graph 火焰圖

go-torch 在 Go 1.11 以前是做爲非官方的可視化工具存在的, 它能夠爲監控數據生成一個相似下面這樣的圖形界面, 紅紅火火的, 於是得名. 從 Go 1.11 開始, 火焰圖被集成進入 Go 官方的 pprof 庫.

go-torch is deprecated, use pprof instead

As of Go 1.11, flamegraph visualizations are available in go tool pprof directly!

1 
$ go tool pprof -http=":8081" [binary] [profile]

在瀏覽器打開 http://localhost:8081/ui/flamegraph, 就能夠看到下面這樣的反過來的火焰圖.

長條形的顏色只是爲了好看, 顏色的深淺是隨機的 = 。= 長度越長表明佔用 CPU 時間越長

而後, pprof 命令行的 top 以及 list 正則也能夠在這裏邊完成, 還有 svg 圖形.

 

基於Chrome的圖形trace/debug

Trace概覽

讓咱們從一個簡單的「Hello，world」示例開始。在本例中，咱們使用runtime/trace包將trace數據寫入標準錯誤輸出。

 

package main

import (    
    "os"    "runtime/trace"
)

func main() {    trace.Start(os.Stderr)    
    defer trace.Stop()    
    // create new channel of type int    ch := make(chan int)    
    
    // start new anonymous goroutine    go func() {        
        // send 42 to channel        ch <- 42    }()    
    // read from channel    <-ch }

 

 

這個例子建立了一個無緩衝的channel，初始化一個goroutine，併發送數字42到channel。運行主goroutine時是阻塞的，它會等待另外一個goroutines發送一個int數值給channel。

用 go run main.go 2> trace.out 運行這段代碼會發送trace數據到trace.out，以後能夠用 go tool trace trace.out 讀取trace。（該程序是個web app，默認啓動127.0.0.1地址的一個隨機端口，若是須要修改host能夠加參數解決，例如 go tool trace --http=':8080' trace.out，譯者加）  

Tips: go 1.8以前，你同時須要可執行二進制文件和trace數據來分析trace；用go 1.8以後的版本編譯的程序，trace數據已經包含了go tool trace命令全部的信息。
運行該命令後，在瀏覽器窗口打開該地址，它會提供一些選項。每個都會打開trace的不一樣視圖，涵蓋了程序執行的不一樣信息。

 

 

 

1 View trace  

最複雜、最強大和交互式的可視化顯示了整個程序執行的時間軸。這個視圖顯示了在每一個虛擬處理器上運行着什麼，以及什麼是被阻塞等待運行的。稍後咱們將在這篇文章中深刻探討這個視圖。注意它只能在chrome上顯示。

2 Goroutine analysis  

顯示了在整個執行過程當中，每種類型的goroutines是如何建立的。在選擇一種類型以後就能夠看到關於這種類型的goroutine的信息。例如，在試圖從mutex獲取鎖、從網絡讀取、運行等等每一個goroutine被阻塞的時間。

3 Network/Sync/Syscall blocking profile  

這些圖表顯示了goroutines在這些資源上所花費的時間。它們很是接近pprof上的內存/cpu分析。這是分析鎖競爭的最佳選擇。

4 Scheduler latency profiler  

爲調度器級別的信息提供計時功能，顯示調度在哪裏最耗費時間。

 

View Trace

 

點擊「View Trace」連接，你會看到一個界面，裏面充滿了關於整個程序執行的信息。Tips: 右上角的"?"按鈕能夠獲取快捷方式列表，以幫助跟蹤trace。
下面的圖片突出了最重要的部分，圖片下面是對每一個部分的說明描述：

 

 

1 Timeline  

顯示執行的時間，根據跟蹤定位的不一樣，時間單位可能會發生變化。你能夠經過使用鍵盤快捷鍵（WASD鍵，就像視頻遊戲同樣）來導航時間軸。

2 Heap  

在執行期間顯示內存分配，這對於發現內存泄漏很是有用，並檢查垃圾回收在每次運行時可以釋放多少內存。

3 Goroutines  

在每一個時間點顯示有多少goroutines在運行，有多少是可運行的（等待被調度的）。大量可運行的goroutines可能顯示調度競爭，例如，當程序建立過多的goroutines，會致使調度程序繁忙。

4 OS Threads  

顯示有多少OS線程正在被使用，有多少個被syscalls阻塞。

5 Virtual Processors  

每一個虛擬處理器顯示一行。虛擬處理器的數量由GOMAXPROCS環境變量控制（默認爲內核數）。

6 Goroutines and events  

顯示在每一個虛擬處理器上有什麼goroutine在運行。鏈接goroutines的連線表明事件。在示例圖片中，咱們能夠看到goroutine "G1.runtime.main"衍生出了兩個不一樣的goroutines:G6和G5（前者是負責收集trace數據的goroutine，後者是咱們使用「go」關鍵字啓動的那個）。每一個處理器的第二行可能顯示額外的事件，好比syscalls和運行時事件。這還包括goroutine表明運行時所作的一些工做（例如輔助垃圾回收）。下圖顯示了當選擇一個goroutine時獲得的信息。

 

 

該信息包含：

  •     它的「名稱」(Title)

  •     什麼時候開始(Start)

  •     持續時間(Wall Duration)

  •     開始時的棧trace

  •     結束時的棧trace

  •     該goroutine產生的事件

咱們能夠看到，這個goroutine創造了兩個事件：

trace goroutine和在channel上發送42的goroutine。

 

 

 

經過點擊一個特定的事件（點擊圖中的一條連線或者在點擊goroutine後選擇事件），咱們能夠看到：

  • 事件開始時的棧信息

  • 事件持續時長

  • 事件包含的goroutine

你能夠點擊這些goroutines來定位跟蹤到它們的trace數據。

 

阻塞概況 

從trace中得到的另外一個特殊視圖是網絡/同步/syscall阻塞概況。阻塞概況顯示了一個相似於pprof的內存/cpu概況中的圖形視圖。不一樣之處在於，這些概況顯示每一個goroutine在一個特定資源上花費的阻塞時間，而不是顯示每一個函數分配了多少內存。下圖告訴咱們示例代碼的「同步阻塞概況」

這告訴咱們，咱們的主goroutine從一個channel接收花費了12.08微秒。當太多的goroutines在競爭着獲取一個資源的鎖時，這種類型的圖是找到鎖競爭的很好的方法。

收集trace

有三種收集trace的方法：

1 使用 runtime/trace包  

這個須要調用trace.Start和trace.Stop，已經在咱們的示例程序中講過。

2 使用 -trace=<file>測試標誌  

用來收集關於被測試代碼的trace時比較有用。

3 使用 debug/pprof/tracehandler  

這是用來收集運行中的web應用的trace的最好的方法。

 

 

跟蹤一個web應用

 


想要從一個運行的web應用收集trace, 你須要添加 /debug/pprof/trace handler。下面的代碼示例展現瞭如何經過簡單地導入 net/http/pprof 包爲 http.DefaultServerMux 作到這一點。

package main

import (    
    "net/http"    _ 
    "net/http/pprof"
)

func main() {    http.Handle("/hello", http.HandlerFunc(helloHandler))    http.ListenAndServe("localhost:8181", http.DefaultServeMux) }

func helloHandler(w http.ResponseWriter, r *http.Request) {    w.Write([]byte("hello world!")) }

 

爲了收集trace，咱們須要向endpoint發出請求，例如，curl localhost:8181/debug/pprof/trace?seconds=10 > trace.out 此請求將阻塞10秒鐘，trace數據將寫入文件trace.out。像這樣生成的trace能夠像咱們之前那樣查看：go tool trace trace.out
Tips: 請注意，將pprof handlers暴露給Internet是不建議的。推薦的作法是在不一樣的只綁定到loopback接口的http.Server暴露這些endpoint。這篇博客（https://mmcloughlin.com/posts/your-pprof-is-showing）討論該風險，並有代碼示例解釋如何正確地暴露pprof handler。

在收集trace以前，讓咱們首先經過wrk來給咱們的服務加一些負載：$ wrk -c 100 -t 10 -d 60s http://localhost:8181/hello

這將使用10個線程的100個鏈接在60秒內發出請求。當wrk正在運行時，咱們可使用 curl localhost:8181/debug/pprof/trace?seconds=5 > trace.out 來收集5s的trace數據。這會產生一個5MB的文件（若是咱們可以在個人4核CPU機器上生成更多的負載，它就能夠快速增加）。一樣，打開trace是由go tool trace命令完成的。當該工具解析文件的整個內容時，這將花費比咱們以前的示例花費的時間更長。當它完成時，頁面看起來略有不一樣：

 

View trace (0s-2.546634537s)
View trace (2.546634537s-5.00392737s)

Goroutine analysis
Network blocking profile
Synchronization blocking profile
Syscall blocking profile
Scheduler latency profile


爲了保證瀏覽器渲染呈現全部內容，該工具將trace分爲兩個連續的部分。更復雜的應用或更長的trace可能須要工具將其分割成更多的部分。點擊「View trace(2.546634537-5.00392737)」咱們能夠看到有不少事情正在發生：

這個特殊的屏幕截圖顯示了一個GC運行狀況，它從1169ms-1170ms開始，在1174ms以後結束。在這段時間裏，一個OS線程（PROC 1）運行一個用於GC的goroutine，而其餘goroutines則在一些GC階段中提供輔助（這些步驟顯示在goroutine的連線中，並被叫作MARK ASSIST)。在截圖的最後，咱們能夠看到大部分分配的內存都被GC釋放了。  另外一個特別有用的信息是在「Runnable」狀態下的goroutines的數量（在選定的時間內是13）：若是這個數字隨着時間的推移變得很大，這就意味着咱們須要更多的cpu來處理負載。

 

結論


trace程序是調試併發問題的強大工具。例如，競爭和邏輯衝突。但它並不能解決全部的問題：它並非用來跟蹤哪塊代碼花費最多CPU時間或分配的最佳工具。go tool pprof 更適用於這些用例。當你想要了解一個耗時程序的行爲，而且想知道當每一個goroutine不運行時它在作什麼，這個工具就會很好地發揮做用。收集trace可能會有一些開銷，而且會生成大量的數據用來檢查。不幸的是，官方文檔是缺失的，所以須要進行一些試驗來嘗試和理解trace程序所顯示的內容。這也是對官方文檔和整個社區做出貢獻的機會（e.g 博客文章)。

 

參考 

Go execution tracer (design doc)

Using the go tracer to speed fractal rendering

Go tool trace

Your pprof is showing