如何擷取啟動並執行go程式的profile資訊

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。go程式從開始運行起，runtime就按照一定頻率對記憶體配置進行採樣記錄：當記憶體配置每達到一定值（預設是512KB，由[`runtime.MemProfileRate`](https://golang.google.cn/pkg/runtime/#pkg-variables)設定）, runtime就會記錄下當前這次記憶體配置的大小，call stack等資訊到profile裡面。而CPU的profile是從調用[`runtime/pprof包的pprof.StartCPUProfile()`](https://golang.google.cn/pkg/runtime/pprof/#StartCPUProfile)開始，到[`pprof.StopCPUProfile()`](https://golang.google.cn/pkg/runtime/pprof/#StopCPUProfile)結束，每1秒採樣100次，每次採樣時記錄下當前正在執行的所有goroutine的call stack，某個函數在這些快照裡面出現的次數越多就說明這個函數越耗時。啟動並執行go程式的所有profile資訊都是通過在運行時調用[`runtime/pprof`](https://golang.google.cn/pkg/runtime/pprof/)和[`runtime/trace`](https://golang.google.cn/pkg/runtime/trace/)兩個包的介面擷取，調用這些介面的方式有直接調用和通過http請求間接調用兩種，下面我們說明各種常用的profile資訊以及它們的擷取，使用方式。#### 1. **當前所有goroutine的函數調用棧****用處：**查看當前有哪些goroutine在運行，數量對不對，有沒有出現很多goroutine卡在同一個地方的情況，有沒有死結的情況，間隔的重新整理頁面看看各個goroutine數量變化情況，瞭解程式健全狀態變化。**通過http請求間接擷取：**在程式中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)並只使用它的初始化：import _ "net/http/pprof"這一句導致[`源碼裡面實際執行的是`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L71):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) }上面的url和處理函數都被[`註冊到了http包的DefaultServeMux裡面`](https://github.com/golang/go/blob/master/src/net/http/server.go#L2374)，所以要想使用這些url就必須使用DefaultServeMux來監聽某一連接埠：http.ListenAndServe(":9999", nil)這裡第一個參數可以是原生任一連接埠，[`當第二個參數為nil時就使用http包的DefaultServeMux來監聽並處理http請求`](https://golang.google.cn/pkg/net/http/#ListenAndServe)， 或者當程式裡面已經有自訂的ServeMux時，可以像上面的init函數那樣把pprof的處理函數[`註冊到自訂的ServeMux`](https://golang.google.cn/pkg/net/http/#ServeMux.HandleFunc)。在程式裡面添加上面的代碼後，運行時我們可以通過瀏覽器或wget訪問下面的http地址查看goroutine資訊：http://localhost:9999/debug/pprof/goroutine?debug=1或者進入index頁面查看更多項：http://localhost:9999/debug/pprof**直接擷取：**不常用，可以查看[`源碼`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L224)#### 2. **一段時間內的CPU profile****用處：**查看消耗CPU的熱點函數，能否減少調用次數，能否避免重複計算。**通過http請求間接擷取：**同第1點裡面擷取goroutine資訊一樣，在程式中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)並只使用它的初始化：import _ "net/http/pprof"然後使用DefaultServeMux來監聽某一連接埠：http.ListenAndServe(":9999", nil)在程式裡面添加上面的代碼後，運行時我們可以通過瀏覽器或wget訪問下面的http地址擷取CPU profile：http://localhost:9999/debug/pprof/profile?seconds=30這個http請求會等seconds參數指定的秒數，這期間讀取請求返回的二進位格式內容，我們把返回的內容儲存為檔案，假設取名為cpu.prof, 這個檔案裡麵包含了程式收到請求後的seconds秒內運行佔用CPU的情況。接下來我們通過在命令列輸入[`go tool pprof`](https://golang.google.cn/cmd/pprof/)來查看cpu.prof:go tool pprof cpu.prof這個命令會進入命令列互動，我們可以輸入很多子命令來查看相關資訊，最常用的幾個子命令是：top N該子命令會列出最耗時的N個函數調用，在輸入top命令前輸入cum或flat可以使得top列出的列表按cum或flat列排序，flat是單個函數自身（不計函數裡面調用的其它函數）的耗時，cum是函數從進入到退出總的耗時。如果要看某個函數具體是在什麼地方耗時，可以使用list子命令查看：list func_name_in_top_list該命令會顯示耗時的代碼和行號, 如果提示找不到source資訊，可以在`go tool pprof`後面指定儲存在本地的被profile程式的binary檔案，並且這個binary檔案要和產生profile檔案的程式是在同一平台下編譯的。比如在本地的Windows機器上遠程profile linux機器上啟動並執行go程式時，確保本地指定的binary是linux機器上編譯的：go tool pprof mybinarypath prof_file_from_remote_hostgo tool pprof mybinarypath https://myremotehost/debug/pprof/profile為了更直觀的看出熱點函數的調用關係，我們更多的是使用svg和web子命令：svg > xxx.svgwebsvg命令會產生一個指定檔案名稱的svg檔案，web命令會產生一個svg檔案並用瀏覽器開啟這個檔案，執行web命令前先確保安裝了graphviz（brew install graphviz, 然後brew list graphviz查看安裝位置並將安裝位置的bin目錄加到PATH），並確保svg檔案的預設開啟程式是瀏覽器。 通過web子命令在瀏覽器開啟的這個svg檔案非常有用, 可以清楚的看到耗時函數的呼叫歷程圖。上面是通過瀏覽器或wget擷取cpu.prof檔案，然後使用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)命令來分析這個檔案，更直接的方式是直接在命令列輸入：go tool pprof http://localhost:9999/debug/pprof/profile?seconds=30這個命令會等seconds指定的秒數，這期間讀取請求返回的二進位格式內容並寫入臨時檔案，再用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)查看這個檔案並進入命令列互動，過程和上面儲存到自訂檔案是一樣的。**直接擷取：**上面通過http請求間接擷取的方式實際上最終還是[`url的handler調用了runtime/pprof包的介面`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L105)： import "runtime/pprof" func Profile(w http.ResponseWriter, r *http.Request) {sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64)if sec == 0 {sec = 30}if durationExceedsWriteTimeout(r, float64(sec)) {w.Header().Set("Content-Type", "text/plain; charset=utf-8")w.Header().Set("X-Go-Pprof", "1")w.WriteHeader(http.StatusBadRequest)fmt.Fprintln(w, "profile duration exceeds server's WriteTimeout")return}// Set Content Type assuming StartCPUProfile will work,// because if it does it starts writing.w.Header().Set("Content-Type", "application/octet-stream")if err := pprof.StartCPUProfile(w); err != nil {// StartCPUProfile failed, so no writes yet.// Can change header back to text content// and send error code.w.Header().Set("Content-Type", "text/plain; charset=utf-8")w.Header().Set("X-Go-Pprof", "1")w.WriteHeader(http.StatusInternalServerError)fmt.Fprintf(w, "Could not enable CPU profiling: %s\n", err)return}sleep(w, time.Duration(sec)*time.Second)pprof.StopCPUProfile() } 在查看線上的服務在不同情境下，不同時間段內的運行情況時，使用上面的方式還是很方便的；但在開發或者最佳化的時候，我們會改動一些代碼，然後想和改動前對比下，看看效能是否有提升，這時我們就需要在代碼中確定固定的開始和結束位置來profie，比如某個函數從進入到退出，或某個測試程式從啟動到退出，就不能像上面那樣大致在某個時間點發出http請求，然後大致等一段時間；這時我們需要在程式裡面直接調用[`runtime/pprof`](https://golang.google.cn/pkg/runtime/pprof/)包的介面： import "runtime/pprof" var cpuprofile = flag.String("cpuprofile", "", "write cpu profile `file`") func main() { flag.Parse() if *cpuprofile != "" { f, err := os.Create(*cpuprofile) if err != nil { log.Fatal("could not create CPU profile: ", err) } if err := pprof.StartCPUProfile(f); err != nil { log.Fatal("could not start CPU profile: ", err) } defer pprof.StopCPUProfile() } // ... rest of the program ... } 上面的代碼cup profile的周期是從程式啟動到退出，profile的內容儲存到cpuprofile參數指定的檔案，和前面通過http請求擷取的cpu.prof一樣，我們通過[`go tool pprof`](https://golang.google.cn/cmd/pprof/)來查看這個檔案。除了像上面那樣在程式中加profile的代碼，`go test`命令內建profile功能，可以在運行`go test`命令時指定[`profile相關的flag`](https://golang.google.cn/cmd/go/#hdr-Description_of_testing_flags)，例如下面的命令運行目前的目錄下的測試案例並將cpu和heap profile寫到指定的檔案，然後我們就可以用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)來查看這些profile檔案了：go test -cpuprofile cpu.prof -memprofile mem.prof -bench .#### 3. **程式當前的記憶體使用量情況****用處：**查看當前記憶體佔用，是否有未及時釋放的記憶體，例如不斷增長的slice或map；查看記憶體配置曆史統計，是否有對象分配過於頻繁，能否複用分配的對象。**通過http請求間接擷取：**同第1點裡面擷取goroutine資訊一樣，在程式中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)並只使用它的初始化：import _ "net/http/pprof"然後使用DefaultServeMux來監聽某一連接埠：http.ListenAndServe(":9999", nil)在程式裡面添加上面的代碼後，運行時我們可以通過瀏覽器或wget訪問下面的http地址擷取heap profile：http://localhost:9999/debug/pprof/heap這個http請求會立刻返回二進位格式的內容，我們把返回的內容儲存為檔案，假設取名為mem.prof, 這個檔案裡麵包含了程式當前正在使用的記憶體的佔用情況。接下來我們通過在命令列輸入[`go tool pprof`](https://golang.google.cn/cmd/pprof/)來查看mem.prof:go tool pprof mem.prof這一句是查看分配之後還沒有釋放的記憶體（in-use memory）：要麼正在使用，要麼確實沒有及時釋放；這對於檢查記憶體流失很有協助。我們還可以在上面的命令加入幾個選項：-inuse_space Display in-use memory size, default-inuse_objects Display in-use object counts-alloc_space Display allocated memory size-alloc_objects Display allocated object counts不加上面任何選項時預設是使用`-inuse_space`, 如果我們想看程式從啟動到現在所有分配過的記憶體（包含已經被釋放了的），可以指定`-alloc_space`:go tool pprof -alloc_space mem.prof通過這個命令我們可以查看分配曆史的統計，知道什麼地方分配記憶體過於頻繁，是否可以複用。 上面的這些命令會進入命令列互動，我們可以輸入很多子命令來查看相關資訊，最常用的幾個子命令是：top N該子命令會列出N處分配記憶體最多的代碼所在的函數，在輸入top命令前輸入cum或flat可以使得top列出的列表按cum或flat列排序，flat是單個函數自身（不計函數裡面調用的其它函數）的記憶體佔用，cum是函數總的佔用。如果要看某個函數具體是在什麼地方分配的記憶體，可以使用list子命令查看：list func_name_in_top_list該命令會顯示分配記憶體的代碼和行號。為了更直觀的看出熱點函數的調用關係，我們更多的是使用web子命令：web該命令會產生一個svg檔案並用瀏覽器開啟這個檔案上面是通過瀏覽器或wget擷取mem.prof檔案，然後使用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)命令來查看這個檔案，更直接的方式是直接在命令列輸入：go tool pprof http://localhost:9999/debug/pprof/heap這個命令會將http的返回寫入臨時檔案，再用[`go tool pprof`](https://golang.google.cn/cmd/pprof/)查看這個檔案並進入命令列互動，過程和上面儲存到自訂檔案是一樣的。**直接擷取：** import "runtime/pprof" ... f, err := os.Create(*memprofile) if err != nil { log.Fatal("could not create memory profile: ", err) } runtime.GC() // get up-to-date statistics if err := pprof.WriteHeapProfile(f); err != nil { log.Fatal("could not write memory profile: ", err) } f.Close() 上面的代碼可以在程式的任何地方執行，輸出的檔案的內容就是程式當前的記憶體使用量情況, 和前面通過http請求擷取的mem.prof一樣，我們通過[`go tool pprof`](https://golang.google.cn/cmd/pprof/)來查看這個檔案。#### 4. **一段時間內所有goroutine的調度和執行過程****用處：**前面的3點對於保證程式正常工作很有用，但是如果我們想提高程式的效能，例如在網路IO或資料庫IO很大的情況下如何充分利用CPU來提高處理速度，這時前面3點就不夠用了。我們需要瞭解各個goroutine是如何被調度的，如何同步執行的；網路等待，同步鎖等待，還有系統調用的等待都發生在什麼地方，在這些等待的地方是不是有CPU空閑被浪費了，這些資訊都在trace裡面。**通過http請求間接擷取：**同第1點裡面擷取goroutine資訊一樣，在程式中引入包[`net/http/pprof`](https://golang.google.cn/pkg/net/http/pprof/)並只使用它的初始化：import _ "net/http/pprof"然後使用DefaultServeMux來監聽某一連接埠：http.ListenAndServe(":9999", nil)在程式裡面添加上面的代碼後，運行時我們可以通過瀏覽器或wget訪問下面的http地址擷取trace資訊：http://localhost:9999/debug/pprof/trace?seconds=10這個http請求會等待seconds秒，這期間讀取請求返回的二進位格式內容，我們把返回的內容儲存為檔案，假設取名為trace.out, 這個檔案裡麵包含了這段時間內的trace資訊。接下來我們通過在命令列輸入[`go tool trace`](https://golang.google.cn/cmd/trace/)來查看trace.out:go tool trace trace.out這個命令會開啟一個web服務，然後開啟瀏覽器運行一個web app，顯示有如下title：View traceGoroutine analysisNetwork blocking profileSynchronization blocking profileSyscall blocking profileScheduler latency profile點擊各個title都可以進入查看詳細資料，其中"View trace"是一個UI互動介面，可以按時間軸查看各個goroutine在各個OS thread上的執行順序，關於這個web app的詳細使用方式可以參考[`這篇文章`](https://blog.gopheracademy.com/advent-2017/go-execution-tracer/)。**直接擷取：**上面通過http請求間接擷取的方式實際上最終是[`url的handler調用了runtime/trace包的介面`](https://github.com/golang/go/blob/master/src/net/http/pprof/pprof.go#L139)： import "runtime/trace" func Trace(w http.ResponseWriter, r *http.Request) {sec, err := strconv.ParseFloat(r.FormValue("seconds"), 64)if sec <= 0 || err != nil {sec = 1}if durationExceedsWriteTimeout(r, sec) {w.Header().Set("Content-Type", "text/plain; charset=utf-8")w.Header().Set("X-Go-Pprof", "1")w.WriteHeader(http.StatusBadRequest)fmt.Fprintln(w, "profile duration exceeds server's WriteTimeout")return}// Set Content Type assuming trace.Start will work,// because if it does it starts writing.w.Header().Set("Content-Type", "application/octet-stream")if err := trace.Start(w); err != nil {// trace.Start failed, so no writes yet.// Can change header back to text content and send error code.w.Header().Set("Content-Type", "text/plain; charset=utf-8")w.Header().Set("X-Go-Pprof", "1")w.WriteHeader(http.StatusInternalServerError)fmt.Fprintf(w, "Could not enable tracing: %s\n", err)return}sleep(w, time.Duration(sec*float64(time.Second)))trace.Stop() } 我們可以在程式裡面直接調用[`runtime/trace`](https://golang.google.cn/pkg/runtime/trace/)包的介面： import "runtime/trace" var traceprofile = flag.String("traceprofile", "", "write trace profile `file`") func main() { flag.Parse() if *traceprofile != "" { f, err := os.Create(*traceprofile) if err != nil { log.Fatal("could not create trace profile: ", err) } if err := trace.Start(f); err != nil { log.Fatal("could not start trace profile: ", err) } defer trace.Stop() } // ... rest of the program ... } 上面的代碼trace profile的周期是從程式啟動到退出，profile的內容儲存到traceprofile參數指定的檔案，和前面通過http請求擷取的trace.out一樣，我們通過[`go tool trace`](https://golang.google.cn/cmd/trace/)來查看這個檔案。#### **另外可參考下面的文章做深入瞭解：**[golang 記憶體分析/動態追蹤](https://lrita.github.io/2017/05/26/golang-memory-pprof/)[Profiling Go programs with pprof](https://jvns.ca/blog/2017/09/24/profiling-go-with-pprof/)[Custom pprof profiles](https://rakyll.org/custom-profiles/)[Mutex profile](https://rakyll.org/mutexprofile/)[pprof user interface](https://rakyll.org/pprof-ui/)[Go execution tracer](https://blog.gopheracademy.com/advent-2017/go-execution-tracer/)[go tool trace](https://making.pusher.com/go-tool-trace/)[An Introduction to go tool trace](https://about.sourcegraph.com/go/an-introduction-to-go-tool-trace-rhys-hiltner/)[Go Execution Tracer(design doc)](https://docs.google.com/document/d/1FP5apqzBgr7ahCCgFO-yoVhk4YZrNIDNf9RybngBc14/edit#heading=h.ayzntospglb3)[Go, the unwritten parts](https://rakyll.org/archive/)636 次點擊