你不知道的 Go 之 pprof
簡介
Go 有非常多好用的工具，pprof 可以用來分析一個程序的性能。pprof 有以下 4 種類型：
CPU profiling（CPU 性能分析）：這是最常使用的一種類型。用于分析函數(shù)或方法的執(zhí)行耗時； Memory profiling：這種類型也常使用。用于分析程序的內(nèi)存占用情況； Block profiling：這是 Go 獨有的，用于記錄 goroutine 在等待共享資源花費的時間； Mutex profiling：與 Block profiling 類似，但是只記錄因為鎖競爭導(dǎo)致的等待或延遲。
我們主要介紹前兩種類型。Go 中 pprof 相關(guān)的功能在包runtime/pprof中。
CPU profiling
pprof 使用非常簡單。首先調(diào)用pprof.StartCPUProfile()啟用 CPU profiling。它接受一個io.Writer類型的參數(shù)，pprof會將分析結(jié)果寫入這個io.Writer中。為了方便事后分析，我們寫到一個文件中。
在要分析的代碼后調(diào)用pprof.StopCPUProfile()。那么StartCPUProfile()和StopCPUProfile()之間的代碼執(zhí)行情況都會被分析。方便起見可以直接在StartCPUProfile()后，用defer調(diào)用StopCPUProfile()，即分析這之后的所有代碼。
我們現(xiàn)在實現(xiàn)一個計算斐波那契數(shù)列的第n數(shù)的函數(shù)：
func fib(n int) int {
if n <= 1 {
return 1
}
return fib(n-1) + fib(n-2)
}
然后使用 pprof 分析一下運行情況：
func main() {
f, _ := os.OpenFile("cpu.profile", os.O_CREATE|os.O_RDWR, 0644)
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
n := 10
for i := 1; i <= 5; i++ {
fmt.Printf("fib(%d)=%d\n", n, fib(n))
n += 3 * i
}
}
執(zhí)行go run main.go，會生成一個cpu.profile文件。這個文件記錄了程序的運行狀態(tài)。使用go tool pprof命令分析這個文件：
上面用top命令查看耗時最高的 10 個函數(shù)?？梢钥吹?code style="font-size: 14px;overflow-wrap: break-word;padding: 2px 4px;border-radius: 4px;margin-right: 2px;margin-left: 2px;background-color: rgba(27, 31, 35, 0.05);font-family: "Operator Mono", Consolas, Monaco, Menlo, monospace;word-break: break-all;color: rgb(239, 112, 96);">fib函數(shù)耗時最高，累計耗時 390ms，占了總耗時的 90.70%。我們也可以使用top5和top20分別查看耗時最高的 5 個 和 20 個函數(shù)。
當(dāng)找到耗時較多的函數(shù)，我們還可以使用list命令查看該函數(shù)是怎么被調(diào)用的，各個調(diào)用路徑上的耗時是怎樣的。list命令后跟一個表示方法名的模式：
我們知道使用遞歸求解斐波那契數(shù)存在大量重復(fù)的計算。下面我們來優(yōu)化一下這個函數(shù)：
func fib2(n int) int {
if n <= 1 {
return 1
}
f1, f2 := 1, 1
for i := 2; i <= n; i++ {
f1, f2 = f2, f1+f2
}
return f2
}
改用迭代之后耗時如何呢？我們來測一下。首先執(zhí)行go run main.go生成cpu.profile文件，然后使用go tool pprof分析：
這里 top 看到的列表是空的。因為啟用 CPU profiling 之后，運行時每隔 10ms 會中斷一次，記錄每個 goroutine 當(dāng)前執(zhí)行的堆棧，以此來分析耗時。我們優(yōu)化之后的代碼，在運行時還沒來得及中斷就執(zhí)行完了，因此沒有信息。
go tool pprof 執(zhí)行的所有命令可以通過help查看：
Memory profiling
內(nèi)存分析有所不同，我們可以在程序運行過程中隨時查看堆內(nèi)存情況。下面我們編寫一個生成隨機字符串，和將字符串重復(fù)n次的函數(shù)：
const Letters = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"
func generate(n int) string {
var buf bytes.Buffer
for i := 0; i < n; i++ {
buf.WriteByte(Letters[rand.Intn(len(Letters))])
}
return buf.String()
}
func repeat(s string, n int) string {
var result string
for i := 0; i < n; i++ {
result += s
}
return result
}
編寫程序，調(diào)用上面的函數(shù)，記錄內(nèi)存占用情況：
func main() {
f, _ := os.OpenFile("mem.profile", os.O_CREATE|os.O_RDWR, 0644)
defer f.Close()
for i := 0; i < 100; i++ {
repeat(generate(100), 100)
}
pprof.Lookup("heap").WriteTo(f, 0)
}
這里在循環(huán)結(jié)束后，通過pprof.Lookup("heap")查看堆內(nèi)存的占用情況，并將結(jié)果寫到文件mem.profile中。
運行go run main.go生成mem.profile文件，然后使用go tool pprof mem.profile來分析：
當(dāng)然也可以使用list命令查看，內(nèi)存在哪一行分配的：
結(jié)果在預(yù)期之中，因為字符串拼接要會占用不少臨時空間。
pkg/profile
runtime/pprof使用起來有些不便，因為要重復(fù)編寫打開文件，開啟分析，結(jié)束分析的代碼。所以出現(xiàn)了包裝了runtime/pprof的庫：pkg/profile。pkg/profile的 GitHub 倉庫地址為：https://github.com/pkg/profile。pkg/profile只是對runtime/pprof做了一層封裝，讓它更好用。使用pkg/profile可以將代碼簡化為一行。使用前需要使用go get github.com/pkg/profile獲取這個庫。
defer profile.Start().Stop()
默認(rèn)啟用的是 CPU profiling，數(shù)據(jù)寫入文件cpu.pprof。使用它來分析我們的fib程序性能：
$ go run main.go
2021/06/09 21:10:36 profile: cpu profiling enabled, C:\Users\ADMINI~1\AppData\Local\Temp\profile594431395\cpu.pprof
fib(10)=89
fib(13)=377
fib(19)=6765
fib(28)=514229
fib(40)=165580141
2021/06/09 21:10:37 profile: cpu profiling disabled, C:\Users\ADMINI~1\AppData\Local\Temp\profile594431395\cpu.pprof
控制臺會輸出分析結(jié)果寫入的文件路徑。
如果要啟用 Memory profiling，可以傳入函數(shù)選項MemProfile：
defer profile.Start(profile.MemProfile).Stop()
另外還可以通過函數(shù)選項控制內(nèi)存采樣率，默認(rèn)為 4096。我們可以改為 1：
defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
火焰圖
通過命令行查看 CPU 或內(nèi)存情況不夠直觀。Bredan Gregg 大神發(fā)明了火焰圖（Flame Graph）可以很直觀地看到內(nèi)存和 CPU 消耗情況。新版本的 go tool pprof 工具已經(jīng)集成了火焰圖（我使用的是 Go1.16）。想要生成火焰圖，必須安裝 graphviz。
在 Mac 上：
brew install graphviz
在 Ubuntu 上：
apt install graphviz
在 Windows 上，官網(wǎng)下載頁http://www.graphviz.org/download/有可執(zhí)行安裝文件，下載安裝即可。注意設(shè)置 PATH 路徑。
上面程序生成的 cpu.profile 和 mem.profile 我們可以直接在網(wǎng)頁上查看火焰圖。執(zhí)行下面命令：
go tool pprof -http :8080 cpu.profile
默認(rèn)會打開瀏覽器窗口，顯示下面的頁面：
我們可以在 VIEW 菜單欄中切換顯示火焰圖：
可以用鼠標(biāo)在火焰圖上懸停、點擊，來查看具體的某個調(diào)用。
net/http/pprof
如果線上遇到 CPU 或內(nèi)存占用過高，該怎么辦呢？總不能將上面的 Profile 代碼編譯到生產(chǎn)環(huán)境吧，這無疑會極大地影響性能。net/http/pprof提供了一個方法，不使用時不會造成任何影響，遇到問題時可以開啟 profiling 幫助我們排查問題。我們只需要使用import這個包，然后在一個新的 goroutine 中調(diào)用http.ListenAndServe()在某個端口啟動一個默認(rèn)的 HTTP 服務(wù)器即可：
import (
_ "net/http/pprof"
)
func NewProfileHttpServer(addr string) {
go func() {
log.Fatalln(http.ListenAndServe(addr, nil))
}()
}
下面我們編寫一個 HTTP 服務(wù)器，將前面示例中的求斐波那契數(shù)和重復(fù)字符串搬到 Web 上。為了讓測試結(jié)果更明顯一點，我把原來執(zhí)行一次的函數(shù)都執(zhí)行了 1000 次：
func fibHandler(w http.ResponseWriter, r *http.Request) {
n, err := strconv.Atoi(r.URL.Path[len("/fib/"):])
if err != nil {
responseError(w, err)
return
}
var result int
for i := 0; i < 1000; i++ {
result = fib(n)
}
response(w, result)
}
func repeatHandler(w http.ResponseWriter, r *http.Request) {
parts := strings.SplitN(r.URL.Path[len("/repeat/"):], "/", 2)
if len(parts) != 2 {
responseError(w, errors.New("invalid params"))
return
}
s := parts[0]
n, err := strconv.Atoi(parts[1])
if err != nil {
responseError(w, err)
return
}
var result string
for i := 0; i < 1000; i++ {
result = repeat(s, n)
}
response(w, result)
}
創(chuàng)建 HTTP 服務(wù)器，注冊處理函數(shù)：
func main() {
mux := http.NewServeMux()
mux.HandleFunc("/fib/", fibHandler)
mux.HandleFunc("/repeat/", repeatHandler)
s := &http.Server{
Addr: ":8080",
Handler: mux,
}
NewProfileHttpServer(":9999")
if err := s.ListenAndServe(); err != nil {
log.Fatal(err)
}
}
我們另外啟動了一個 HTTP 服務(wù)器用于處理 pprof 相關(guān)請求。
另外為了測試，我編寫了一個程序，一直發(fā)送 HTTP 請求給這個服務(wù)器：
func doHTTPRequest(url string) {
resp, err := http.Get(url)
if err != nil {
fmt.Println("error:", err)
return
}
data, _ := ioutil.ReadAll(resp.Body)
fmt.Println("ret:", len(data))
resp.Body.Close()
}
func main() {
var wg sync.WaitGroup
wg.Add(2)
go func() {
defer wg.Done()
for {
doHTTPRequest(fmt.Sprintf("http://localhost:8080/fib/%d", rand.Intn(30)))
time.Sleep(500 * time.Millisecond)
}
}()
go func() {
defer wg.Done()
for {
doHTTPRequest(fmt.Sprintf("http://localhost:8080/repeat/%s/%d", generate(rand.Intn(200)), rand.Intn(200)))
time.Sleep(500 * time.Millisecond)
}
}()
wg.Wait()
}
使用命令go run main.go啟動服務(wù)器。運行上面的程序一直發(fā)送請求給服務(wù)器。一段時間之后，我們可以用瀏覽器打開http://localhost:9999/debug/pprof/：
go tool pprof也支持遠(yuǎn)程獲取 profile 文件：
$ go tool pprof -http :8080 localhost:9999/debug/pprof/profile?seconds=120
其中seconds=120表示采樣 120s，默認(rèn)為 30s。結(jié)果如下：
可以看出這里除了運行時的消耗，主要就是fibHandler和repeatHandler這兩個處理的消耗了。
當(dāng)然一般線上不可能把這個端口開放出來，因為有很大的安全風(fēng)險。所以，我們一般在線上機器 profile 生成文件，將文件下載到本地分析。上面我們看到go tool pprof會生成一個文件保存在本地，例如我的機器上是C:\Users\Administrator\pprof\pprof.samples.cpu.001.pb.gz。把這個文件下載到本地，然后：
$ go tool pprof -http :8888 pprof.samples.cpu.001.pb.gz
net/http/pprof 實現(xiàn)
net/http/pprof的實現(xiàn)也沒什么神秘的地方，無非就是在net/http/pprof包的init()函數(shù)中，注冊了一些處理函數(shù)：
// src/net/http/pprof/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)
}
http.HandleFunc()會將處理函數(shù)注冊到默認(rèn)的ServeMux中：
// src/net/http/server.go
var DefaultServeMux = &defaultServeMux
var defaultServeMux ServeMux
func HandleFunc(pattern string, handler func(ResponseWriter, *Request)) {
DefaultServeMux.HandleFunc(pattern, handler)
}
這個DefaultServeMux是net/http的包級變量，只有一個實例。為了避免路徑?jīng)_突，通常我們不建議在自己編寫 HTTP 服務(wù)器的時候使用默認(rèn)的DefaultServeMux。一般都是先調(diào)用http.NewServeMux()創(chuàng)建一個新的ServeMux，見上面的 HTTP 示例代碼。
再來看net/http/pprof包注冊的處理函數(shù)：
// src/net/http/pprof/pprof.go
func Profile(w http.ResponseWriter, r *http.Request) {
// ...
if err := pprof.StartCPUProfile(w); err != nil {
serveError(w, http.StatusInternalServerError,
fmt.Sprintf("Could not enable CPU profiling: %s", err))
return
}
sleep(r, time.Duration(sec)*time.Second)
pprof.StopCPUProfile()
}
刪掉前面無關(guān)的代碼，這個函數(shù)也是調(diào)用runtime/pprof的StartCPUProfile(w)方法開始 CPU profiling，然后睡眠一段時間（這個時間就是采樣間隔），最后調(diào)用pprof.StopCPUProfile()停止采用。StartCPUProfile()方法傳入的是http.ResponseWriter類型變量，所以采樣結(jié)果直接寫回到 HTTP 的客戶端。
內(nèi)存 profiling 的實現(xiàn)用了一點技巧。首先，我們在init()函數(shù)中沒有發(fā)現(xiàn)處理內(nèi)存 profiling 的處理函數(shù)。實現(xiàn)上，/debug/pprof/heap路徑都會走到Index()函數(shù)中：
// src/net/http/pprof/pprof.go
func Index(w http.ResponseWriter, r *http.Request) {
if strings.HasPrefix(r.URL.Path, "/debug/pprof/") {
name := strings.TrimPrefix(r.URL.Path, "/debug/pprof/")
if name != "" {
handler(name).ServeHTTP(w, r)
return
}
}
// ...
}
最終會走到handler(name).ServeHTTP(w, r)。handler只是基于string類型定義的一個新類型，它定義了ServeHTTP()方法：
type handler string
func (name handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
p := pprof.Lookup(string(name))
// ...
p.WriteTo(w, debug)
}
刪掉其他無關(guān)的代碼，就剩下上面兩行。統(tǒng)計數(shù)據(jù)將會寫入http.ResponseWriter。
Benchmark
其實在Benchmark時也可以生成cpu.profile、mem.profile這些分析文件。我們在第一個示例的目錄下新建一個bench_test.go文件：
func BenchmarkFib(b *testing.B) {
for i := 0; i < b.N; i++ {
fib(30)
}
}
然后執(zhí)行命令go test -bench . -test.cpuprofile cpu.profile：
然后就可以分析這個cpu.profile文件了。
總結(jié)
本文介紹了 pprof 工具的使用，以及更方便使用的庫pkg/profile，另外介紹如何使用net/http/pprof給線上程序加個保險，遇到問題隨時可以診斷。沒有遇到問題不會對性能有任何影響。
參考
pkg/profile GitHub：https://github.com/pkg/profile 你不知道的Go GitHub：https://github.com/darjun/you-dont-know-go
推薦閱讀