使用 pprof 和 Flame-Graph 調試 Golang 應用

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

前言

最近用 Golang 實現了一個日誌搜集上報程式(內部稱 logger 項目)，線上灰階測試過程發現 logger 佔用 CPU 非常高(80% - 100%)。而此項目之前就線上上使用，用於消費 NSQ 任務， CPU 佔用一直在 1%，最近的修改只是添加了基於磁碟隊列的生產者消費者服務，生產者使用 go-gin 實現了一個 httpserver，接收資料後寫入磁碟隊列；消費者為單個 goroutine 迴圈 POST 資料。而 httpserver 壓力不大(小於 100 QPS)，不至於佔用如此高的 CPU，大致 review 代碼後未發現異常，藉助 pprof 和 flame-graph 來分析定位問題。

pprof

pprof 我理解是 program profile(即程式效能剖析之意)，Golang 提供的兩個官方包runtime/pprof，net/http/pprof能方便的採集程式啟動並執行堆棧、goroutine、記憶體配置和佔用、io 等資訊的 .prof 檔案，然後可以使用 go tool pprof 分析 .prof 檔案。兩個包的作用是一樣的，只是使用方式的差異。

runtime/pprof

如果程式為非 httpserver 類型，使用此方式；在 main 函數中嵌入如下代碼:

import "runtime/pprof"var cpuprofile = flag.String("cpuprofile"， ""， "write cpu profile `file`")var memprofile = flag.String("memprofile"， ""， "write memory profile to `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 ...    if *memprofile != "" {        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()    }}

運行程式

./logger -cpuprofile cpu.prof -memprofile mem.prof

可以得到 cpu.prof 和 mem.prof 檔案，使用 go tool pprof 分析。

go tool pprof logger cpu.profgo tool pprof logger mem.prof

net/http/pprof

如果程式為 httpserver 類型， 則只需要匯入該包:

import _ "net/http/pprof"

如果 httpserver 使用 go-gin 包，而不是使用預設的 http 包啟動，則需要手動添加 /debug/pprof 對應的 handler，github 有封裝好的模版:

import "github.com/DeanThompson/ginpprof"...router := gin.Default()ginpprof.Wrap(router)...

匯入包重新編譯器後運行，在瀏覽器中訪問 http://host:port/debug/pprof 可以看到如下資訊，這裡 host 和 port 是程式綁定的 host 和 port，例如我自己的 logger 程式，訪問如下地址:

http://127.0.0.1:4500/debug/pprof/

/debug/pprof/profiles:0block62goroutine427heap0mutex12threadcreatefull goroutine stack dump

點擊對應的 profile 可以查看具體資訊，通過瀏覽器查看的資料不能直觀反映程式效能問題，go tool pprof 命令列工具提供了豐富的工具集:

查看 heap 資訊

go tool pprof http://127.0.0.1:4500/debug/pprof/heap

查看 30s 的 CPU 採樣資訊

go tool pprof http://127.0.0.1:4500/debug/pprof/profile

其他功能使用參見官方 net/http/pprof 庫

pprof CPU 分析

採集 profile 資料之後，可以分析 CPU 熱點代碼。執行下面命令：

go tool pprof http://127.0.0.1:4500/debug/pprof/profile

會採集 30s 的 profile 資料，之後進入終端互動模式，輸入 top 指令。

~ # go tool pprof http://127.0.0.1:4500/debug/pprof/profileFetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/profileSaved profile in /home/vagrant/pprof/pprof.logger.samples.cpu.012.pb.gzFile: loggerType: cpuTime: Jan 19， 2018 at 2:01pm (CST)Duration: 30s， Total samples = 390ms ( 1.30%)Entering interactive mode (type "help" for commands， "o" for options)(pprof) topShowing nodes accounting for 360ms， 92.31% of 390ms totalShowing top 10 nodes out of 74      flat  flat%   sum%        cum   cum%     120ms 30.77% 30.77%      180ms 46.15%  compress/flate.(*compressor).findMatch /usr/local/go/src/compress/flate/deflate.go     100ms 25.64% 56.41%      310ms 79.49%  compress/flate.(*compressor).deflate /usr/local/go/src/compress/flate/deflate.go      60ms 15.38% 71.79%       60ms 15.38%  compress/flate.matchLen /usr/local/go/src/compress/flate/deflate.go      20ms  5.13% 76.92%       20ms  5.13%  compress/flate.(*huffmanBitWriter).indexTokens /usr/local/go/src/compress/flate/huffman_bit_writer.go      10ms  2.56% 79.49%       10ms  2.56%  compress/flate.(*huffmanBitWriter).writeTokens /usr/local/go/src/compress/flate/huffman_bit_writer.go      10ms  2.56% 82.05%       10ms  2.56%  hash/adler32.update /usr/local/go/src/hash/adler32/adler32.go      10ms  2.56% 84.62%       10ms  2.56%  runtime.futex /usr/local/go/src/runtime/sys_linux_amd64.s      10ms  2.56% 87.18%       10ms  2.56%  runtime.memclrNoHeapPointers /usr/local/go/src/runtime/memclr_amd64.s      10ms  2.56% 89.74%       10ms  2.56%  runtime.pcvalue /usr/local/go/src/runtime/symtab.go      10ms  2.56% 92.31%       10ms  2.56%  runtime.runqput /usr/local/go/src/runtime/runtime2.go(pprof)

從統計可以 top5 操作全是資料壓縮操作， logger 程式本身開啟了壓縮等級為 9 的 gzip 壓縮，如果希望減少壓縮 CPU 佔用，可以調整壓縮等級。

pprof mem 分析

同時 pprof 也支援記憶體相關資料分析

--inuse_space 分析常駐記憶體

go tool pprof -alloc_space http://127.0.0.1:4500/debug/pprof/heap

~ # go tool pprof -alloc_space http://127.0.0.1:4500/debug/pprof/heapFetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heapSaved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.006.pb.gzFile: loggerType: alloc_spaceTime: Jan 19， 2018 at 2:21pm (CST)Entering interactive mode (type "help" for commands， "o" for options)(pprof) topShowing nodes accounting for 47204.90MB， 99.16% of 47606.01MB totalDropped 230 nodes (cum <= 238.03MB)Showing top 10 nodes out of 39      flat  flat%   sum%        cum   cum%28290.79MB 59.43% 59.43% 28290.79MB 59.43%  bytes.makeSlice /usr/local/go/src/bytes/buffer.go 8706.78MB 18.29% 77.72% 10082.12MB 21.18%  compress/flate.NewWriter /usr/local/go/src/compress/flate/deflate.go 8559.74MB 17.98% 95.70%  8559.74MB 17.98%  github.com/nsqio/go-diskqueue.(*diskQueue).readOne /home/vagrant/go/src/github.com/nsqio/go-diskqueue/diskqueue.go 1343.78MB  2.82% 98.52%  1343.78MB  2.82%  compress/flate.(*compressor).init /usr/local/go/src/compress/flate/deflate.go  298.81MB  0.63% 99.15%   298.81MB  0.63%  github.com/nsqio/go-nsq.ReadResponse /home/vagrant/go/src/github.com/nsqio/go-nsq/protocol.go       2MB 0.0042% 99.15% 12097.28MB 25.41%  main.(*PostPublisher).Publish /home/vagrant/logger/src/handler.go    1.50MB 0.0032% 99.15% 26358.53MB 55.37%  io/ioutil.readAll /usr/local/go/src/io/ioutil/ioutil.go       1MB 0.0021% 99.16% 26378.74MB 55.41%  github.com/gin-gonic/gin.LoggerWithWriter.func1 /home/vagrant/go/src/github.com/gin-gonic/gin/logger.go    0.50MB 0.0011% 99.16% 26434.42MB 55.53%  net/http.(*conn).serve /usr/local/go/src/net/http/server.go         0     0% 99.16% 26357.03MB 55.36%  bytes.(*Buffer).ReadFrom /usr/local/go/src/bytes/buffer.go(pprof)

--alloc_objects 分析臨時記憶體

 go tool pprof -inuse_space http://127.0.0.1:4500/debug/pprof/heap

~ # go tool pprof -inuse_space http://127.0.0.1:4500/debug/pprof/heapFetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heapSaved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gzFile: loggerType: inuse_spaceTime: Jan 19， 2018 at 2:24pm (CST)Entering interactive mode (type "help" for commands， "o" for options)(pprof) topShowing nodes accounting for 20441.23kB， 100% of 20441.23kB totalShowing top 10 nodes out of 35      flat  flat%   sum%        cum   cum%18071.75kB 88.41% 88.41% 18071.75kB 88.41%  bytes.makeSlice /usr/local/go/src/bytes/buffer.go  815.27kB  3.99% 92.40%   815.27kB  3.99%  github.com/nsqio/go-diskqueue.(*diskQueue).readOne /home/vagrant/go/src/github.com/nsqio/go-diskqueue/diskqueue.go  528.17kB  2.58% 94.98%   528.17kB  2.58%  regexp.(*bitState).reset /usr/local/go/src/regexp/backtrack.go     514kB  2.51% 97.50%      514kB  2.51%  net/http.newBufioWriterSize /usr/local/go/src/bufio/bufio.go  512.05kB  2.50%   100%   512.05kB  2.50%  net/http.(*persistConn).roundTrip /usr/local/go/src/net/http/transport.go         0     0%   100%   528.17kB  2.58%  _/home/vagrant/logger/src/parser.ParserLogForMarco /home/vagrant/logger/src/parser/parser.go         0     0%   100%   528.17kB  2.58%  bytes.(*Buffer).ReadFrom /usr/local/go/src/bytes/buffer.go         0     0%   100% 17543.58kB 85.82%  bytes.(*Buffer).Write /usr/local/go/src/bytes/buffer.go         0     0%   100% 17543.58kB 85.82%  bytes.(*Buffer).grow /usr/local/go/src/bytes/buffer.go         0     0%   100%   528.17kB  2.58%  github.com/gin-gonic/gin.(*Context).Next /home/vagrant/go/src/github.com/gin-gonic/gin/context.go(pprof)

通過常駐記憶體和臨時記憶體配置 top 值，可以查看當前程式的記憶體佔用情況和熱點記憶體使用量的代碼，結合程式碼分析熱點代碼是否存在 bug、是否有最佳化的空間。

go-torch

通過上面的 go tool pprof 工具和 top 指令，我們能定位出程式的熱點代碼，但缺乏對程式運行情況的整體感知，能不能有類似火焰圖的效果讓我們對整個堆棧統計資訊有個一目瞭然的效果呢？這裡要感謝 uber 開源的工具 go-torch，能讓我們將 profile 資訊轉換成火焰圖，具體安裝和使用過程見項目的介紹。

安裝好 go-torch 後，運行

go-torch -u http://127.0.0.1:4500

產生 CPU 火焰圖

能一眼看到 publish 函數中的壓縮操作佔了 70% 左右的 CPU。

而 gin httpserver 只佔用了 2% 左右的 CPU， 和我們使用 go tool pprof 的 top 命令分析的結果一致。

預設情況下 go-torch 採集的是 CPU 的 profile， 這裡介紹下 mem 火焰圖的採集。

inuse_space 火焰圖

go-torch -inuse_space http://127.0.0.1:4500/debug/pprof/heap --colors=mem

alloc_space 火焰圖

go-torch -alloc_space http://127.0.0.1:4500/debug/pprof/heap --colors=mem

logger 100% CPU 分析

前面介紹了 go tool pprof 和火焰圖的使用方法，這裡使用火焰圖複現 logger 100% CPU 問題。

先看現象， 用 wrk 壓測 logger

wrk -t1 -c100 -d30 --script=post.lua 'http://127.0.0.1:4500/marco/log'

查看 CPU 佔用情況

採集 30s 的 CPU profile 火焰圖

圖中紅色標記部分 startSink 函數中 runtime.selectgo 消耗了大量 CPU， 而 runtime.selectgo 上面只有 runtime.sellock 和 runtime.selunlock 兩個操作，即大量 CPU 耗費在 select 操作上，火焰圖呈禿頂狀態，即瓶頸所在。

查看 startSink 實現

    for {        if exit == true {            return        }        if moveforward {            fakeRead = readChan        } else {            fakeRead = nil        }        select {        case read := <-fakeRead:            count++            buf.Write(read)        case <-done:            DiskQueue.Close()            exit = true        default:            //pass        }        if count == GlobalConf.CntBatch || exit == true {            hostPoolResponse := pool.Get()            addr := hostPoolResponse.Host()            err := handler.Publish(fmt.Sprintf("%s%s"， addr， SinkConf.Uri)， buf.Bytes())            hostPoolResponse.Mark(err)            if err != nil {                Log.Error("%s"， err.Error())                moveforward = false                time.Sleep(1 * time.Second)                continue            } else {                moveforward = true            }            buf.Reset()            count = 0        }    }

本希望通過 moveforward 來控制 fakeRead 是否取值，而如果 fakeRead 為 nil 時， 整個 select 會一直阻塞，所以加上了 default 操作，讓 select 變成非阻塞，但因為一直沒有讀取內容，count 沒有增加而不會觸發 sleep 操作。最終導致非阻塞的 select 一直空轉迴圈，類似一個空 while 迴圈，佔用了大量 CPU。

最佳化

改用其他方法實現這部分邏輯，這裡不再貼出來了，重在分享發現問題的過程，改進後的火焰圖在前面已給出。

總結

Golang 應用通常只要能編譯通過，很少有運行時問題；而當應用遇到高CPU 、高記憶體佔用或者作為 http 服務端回應時間長，QPS 上不去等，且不能 code review 解決時，可以嘗試使用pprof 和 Flame-Graph 來分析定位問題，有奇效。當然 Golang 程式的調試及調優還有很多方法，比如直接結合go test 和 benchmark通過測用例分析熱點代碼、使用 go pprof分析彙編代碼等。

Tweet