一看就懂系列之Golang的pprof

前言

這是一篇給網友的文章，正好最近在研究分析golang的性能，我以爲是時候來一個了斷了。

正文

1.一句話簡介

Golang自帶的一款開箱即用的性能監控和分析工具。

（全篇看的過程當中不必特地記憶、看完天然讓你有不同的感受）

2.使用姿式？

2.1 runtime/pprof

手動調用runtime.StartCPUProfile/runtime.StopCPUProfile等API來進行數據的採集。

優勢：靈活性高、按需採集。

使用場景：工具型應用（好比說定製化的分析小工具、集成到公司監控系統）

2.2 net/http/pprof

經過http服務來獲取Profile採樣文件。 import _ "net/http/pprof"

優勢：簡單易用。

使用場景：在線服務（一直運行着的程序）

(net/http/pprof中只是使用runtime/pprof包來進行封裝了一下，並在http端口上暴露出來)

2.3 go test

經過命令go test -bench . -cpuprofile cpu.prof來進行採集數據。

優勢：針對性強、細化到函數

使用場景：進行某函數的性能測試

3 分析姿式？

3.1 數據採集

分析的基礎是獲得相應的採集文件。runtime/pprof 和 go test 這兩個均爲命令行採集獲得（下文以分析cpu的進行舉例））。而net/http/pprof經過接口的方式將數據突出。

1.go test的方式很簡單，命令：go test -bench . -cpuprofile cpu.prof 就能夠生成。

2.runtime/pprof，直接上一個最簡單的代碼。

package main

import (
	"fmt"
	"os"
	"runtime/pprof"
	"time"
)

// 一段有問題的代碼
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有問題的那一行，由於收不到值：%v", v)
		default:
		}
	}
}

func main() {

	// 建立分析文件
	file, err := os.Create("./cpu.prof")
	if err != nil {
		fmt.Printf("建立採集文件失敗, err:%v\n", err)
		return
	}

	// 進行cpu數據的獲取
	pprof.StartCPUProfile(file)
	defer pprof.StopCPUProfile()

	// 執行一段有問題的代碼
	for i := 0; i < 4; i++ {
		go do()
	}
	time.Sleep(10 * time.Second)
}
複製代碼

執行命令：

go run pprof.go
複製代碼

而後會獲得數據採集文件：cpu.prof。(這個文件後文會用到)

3.http的方式，上代碼：

package main

import (
	"fmt"
	"net/http"
    _ "net/http/pprof"  // 第一步～
)

// 一段有問題的代碼
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有問題的那一行，由於收不到值：%v", v)
		default:
		}
	}
}

func main() {
	// 執行一段有問題的代碼
	for i := 0; i < 4; i++ {
		go do()
	}
	http.ListenAndServe("0.0.0.0:6061", nil)
}
複製代碼

經過代碼中的關鍵兩步，執行起來就能夠經過 http://127.0.0.1:6061/debug/pprof/看到對應的數據啦～

3.2 數據內容

不論是前文哪一種方式獲取，均可以進行分析。這裏http的方式把能夠看到的信息所有都列出來了。

類型	描述
allocs	內存分配狀況的採樣信息
blocks	阻塞操做狀況的採樣信息
cmdline	顯示程序啓動命令參數及其參數
goroutine	顯示當前全部協程的堆棧信息
heap	堆上的內存分配狀況的採樣信息
mutex	鎖競爭狀況的採樣信息
profile	cpu佔用狀況的採樣信息，點擊會下載文件
threadcreate	系統線程建立狀況的採樣信息
trace	程序運行跟蹤信息

經過加粗的關鍵字，很直觀能夠看到能分析到的數據。

（後文將重點根據cpu的採樣信息展開命令行和圖形化頁面的討論，其他項將在實戰中應用）

3.3 數據分析

3.3.1 命令行

核心命令：go tool pprof <binary> <source>

binary：表明二進制文件路徑。

source：表明生成的分析數據來源，能夠是本地文件（前文生成的cpu.prof），也能夠是http地址（好比：go tool pprof http://127.0.0.1:6060/debug/pprof/profile）

須要注意的是：較大負載的狀況下（要不就故意寫故障代碼，或者就模擬訪問壓力）獲取的有效數據更有意義，若是處於空閒狀態，獲得的結果可能意義不大

開始分析前文生成的cpu.prof:

go tool pprof cpu.prof
複製代碼

看到頁面：

咱們的目標是分析cpu那裏耗時比較多，這裏和linux命令有點像也是輸入： top

這個圖要好好說說！因爲我在理的時候，我以爲要結合具體的圖一塊兒看，才更好理解，因此提供兩種方式來生成圖：

1.在前文的對話框中繼續輸入：web。便可生成pprof001.svg的頁面。

2.執行命令：go tool pprof -pdf cpu.prof,會生成profile001.pdf的pdf文件。(參數可選text、pdf、svg)

無論哪一種形式，都會獲得如下圖片：

類型	描述	舉例
flat	該函數佔用CPU的耗時	selectnbrecv佔用CPU的耗時是12.29s
flat%	該函數佔用CPU的耗時的百分比	selectnbrecv耗時：12.29s，cpu總耗時：29.14，12.29/29.14=42.18
sum%	top命令中排在它上面的函數以及本函數flat%之和	chanrecv：42.18%+30.47% = 72.65%
cum	當前函數加上該函數調用以前的累計CPU耗時	chanrecv：8.88+0.54=9.42
cum%	當前函數加上該函數調用以前的累計CPU耗時的百分比	9.42/29.14=32.33%
最後一列	當前函數名稱	-

發現途中越粗表明越有問題耗時越高，越可能存在問題。發現do函數有點問題。此時經過命令：list funcName，來進行查看具體的位置

發現有問題的行數在文中具體的位置，原來是卡住了，加上default休眠n秒便可解決。

關於mem的分析同cpu相似，本文不在贅述。

總結一下，至少要記住分析三步走：top -> list Func -> web

3.3.2 可視化頁面

兩種方式能夠支持瀏覽器打開web站：

1.執行命令：go tool pprof -http=:6060 cpu.prof

• Top （同前文gdb交互頁面的top命令）

• Graph（同前文gdb交互頁面的web命令）

• Flame Graph（火焰圖）

這裏的顏色是隨機分佈的，只是看起來像火焰。

調用順序由上到下，每一塊表明一個函數，越大表明佔用 CPU 的時間更長。同時它也能夠支持點擊塊深刻進行分析。

• Peek（詳細=樹結構）

• Source（同前文gdb交互頁面的list FuncName命令）

  

• Disassemble

4.遊戲中實戰

西遊記中師徒四人西天取經，歷經九九八十一難，方可取得真經。

這邊已經爲小夥伴弄好了取經小腳本：點我

直接在瀏覽器中執行./xiyouji，即可看到師徒四人一路上的吃喝拉撒。

4.1 第一難-CPU佔用太高

首先先看看profile文件，看看有沒有cpu的異常

go tool pprof http://localhost:6060/debug/pprof/profile
複製代碼

猛然發現這個豬八戒在吃上面有點問題。

因而咱們看看，執行命令：list Drink

原來吃上面有問題，進行了1億次的空循環，怪不得佔CPU那麼高。

咱們在看看大圖：web

此時修復問題便可。（備註掉便可修復，後文同）

4.2 第二難-內存佔用太高

從新編譯事後，繼續前行。接下來看看內存有沒問題。

go tool pprof http://localhost:6060/debug/pprof/heap 
複製代碼

發現沙和尚彷佛吃的比較多？

進一步看看爲何：list Eat

原來這裏進行了惡意的內存追加，直到容量見頂

繼續看看圖，再次確認下：web

修復代碼便可。

4.3 第三難-頻繁內存回收

咱們都知道gc的頻繁處理會致使stw不斷出現，是一個高性能的服務不能容忍的。

這邊須要藉助一個環境變量來啓動gc的觀察,

GODEBUG=gctrace=1 ./xiyouji 2>&1|grep gc
複製代碼

這個信息的說明：

能夠看到基本上3s左右就會觸發一次gc，每次都會從16M->0，說明內存被不斷的申請和釋放。

經過內存的分配狀況，能夠看gc是否存在異常，若是一直佔着100%或者很大比例那說明是有問題的。

執行命令：

go tool pprof http://localhost:6060/debug/pprof/allocs
複製代碼

繼續查看悟空怎麼回事：list Shit

看大圖：web

同前文，備註掉代碼便可繼續前行。

知識點：這邊須要注意的是爲何設置16m呢？簡單說這樣才能在逃逸分析的時候，內存的申請從棧跑到堆上，這樣才能引發gc回收。（更多詳情請查看我還沒寫的《一看就懂系列之Golang的逃逸分析》）

4.4 第四難-協程泄露

咱們發像goroutine好像有點偏多？是否是協程泄漏了？繼續往下看。

查看goroutine狀況：

go tool pprof http://localhost:6060/debug/pprof/goroutine
複製代碼

看到一個引發了不少goroutine的函數，可是彷佛看不到人工添加的函數引起的問題。

繼續追大圖：web

原來是唐僧睡覺的時候有問題。

繼續追查有問題的函數：list Sleep

解決掉問題，再看看http://127.0.0.1:6060/debug/pprof/,發現已經恢復正常。

4.5 第五難-鎖的爭用

有發現一個異常：goroutine已經降到了4個，爲何還有一個鎖的徵用問題？

go tool pprof localhost:6060/debug/pprof/mutex
複製代碼

能夠看到，126行主協程在進行lock加鎖後，立馬再次加鎖，可是解鎖由另外一個協程去unlock，另外一個協程足足休眠1s，這裏會致使阻塞，形成鎖爭用問題。

解決掉便可（備註它）

4.6 第六難-阻塞操做

解決完前文的問題後，發現：

除了鎖形成阻塞外，居然還有其餘邏輯形成阻塞，繼續往下看。

go tool pprof localhost:6060/debug/pprof/block
複製代碼

能夠明顯看到，這裏不一樣於前文的slepe阻塞，是一個channel阻塞，要等1s以後纔有數據輸出，致使這裏程序阻塞了1s。

4.7 第七難-一場誤會

解決完前文全部問題後，仍是發現block有1個？抱着嚴謹的態度，繼續追查。

go tool pprof localhost:6060/debug/pprof/block
複製代碼

原來是http監聽，符合預期。

4.8 第八難-取得真經

通過前文的屢次操做，相信你已經很熟悉排查流程和能排查的內容了。

這裏總結一下排查套路。

第一步：進入排除對應的gdb交互。

go tool pprof http://localhost:6060/debug/pprof/{填上你想查看的內容}
複製代碼

內容關鍵字：

類型	描述
allocs	內存分配狀況的採樣信息
blocks	阻塞操做狀況的採樣信息
cmdline	顯示程序啓動命令參數及其參數
goroutine	顯示當前全部協程的堆棧信息
heap	堆上的內存分配狀況的採樣信息
mutex	鎖競爭狀況的採樣信息
profile	cpu佔用狀況的採樣信息，點擊會下載文件
threadcreate	系統線程建立狀況的採樣信息
trace	程序運行跟蹤信息

第二步：三聯招，top->list FuncName->web

經過佔用比分析，查看具體代碼行數，看大圖確認。

第三步：解決問題。

（細心的同窗可能會發現沒有對trace進行分析，這個請期待《一看就懂系列之Golang的trace》）

5.與測試命令共舞

測試分析特別簡單，在原有的命令後加上-cpuprofile=cpu.prof或-memprofile=mem.prof就能夠獲得對應的數據採集文件啦，後面的事對於已經取得真經的你應該懂的

命令例子：go test -bench . -cpuprofile cpu.prof

參考文獻

1.Golang 大殺器之性能剖析 PProf

2.golang pprof 實戰

3.Go 程序的性能監控與分析 pprof

4.go pprof 性能分析

5.如何監控 golang 程序的垃圾回收