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

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