前言
最近用 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分析匯編代碼等。
推薦閱讀：