前言
最近用 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.prof
go 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: 0 block 62 goroutine 427 heap 0 mutex 12 threadcreate full 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/profile Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/profile Saved profile in /home/vagrant/pprof/pprof.logger.samples.cpu.012.pb.gz File: logger Type: cpu Time: 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) top Showing nodes accounting for 360ms， 92.31% of 390ms total Showing 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/heap Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heap Saved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.006.pb.gz File: logger Type: alloc_space Time: Jan 19， 2018 at 2:21pm (CST) Entering interactive mode (type "help" for commands， "o" for options) (pprof) top Showing nodes accounting for 47204.90MB， 99.16% of 47606.01MB total Dropped 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/heap Fetching profile over HTTP from http://127.0.0.1:4500/debug/pprof/heap Saved profile in /home/vagrant/pprof/pprof.logger.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gz File: logger Type: inuse_space Time: Jan 19， 2018 at 2:24pm (CST) Entering interactive mode (type "help" for commands， "o" for options) (pprof) top Showing nodes accounting for 20441.23kB， 100% of 20441.23kB total Showing 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分析彙編程式碼等。
推薦閱讀：