http://yangxikun.com/golang/2017/12/24/golang-profiling-optimizing.html
本文總結自 Profiling and Optimizing Go
[1]，對應的 PPT[2]，有梯子的可以直接看視頻，沒梯子的也可以看下這篇文章:) 。Golang 的 runtime 內建了強大的分析工具 pprof，能幫助我們對程序運行時的 CPU、內存進行分析。
首先，跟隨視頻，將作者提供的代碼 clone 下來。在我們的工作區執行 go get -v github.com/prashantv/go_profiling_talk即可。
進入src/github.com/prashantv/go_profiling_talk，master 分支是優化過的最快的版本，slow 分支是優化前的版本，執行go run main.go即可啟動一個 http 服務。
代碼說明：
- 以一個 http 服務運行，有兩個請求路徑/hello和/simple
- /hello的請求會增加一些統計信息的記錄，然後輸出Hello world
- /simple的請求則是簡單的輸出Hello world!
- 實踐目的：通過 pprof 分析優化/hello接口的性能，使其與/simple接口的性能差距儘量小。
先來看看未優化前/hello和/simple的性能對比：
很明顯/hello要比/simple慢很多，接下來就開始我們的性能分析之旅。首先需要保證/hello接口處於壓測狀態，因為這樣才能進行性能分析的數據採樣。
執行~/Software/go-app/bin/go-wrk -d 500 http://localhost:9090/hello進行 500s 的持續壓測。
訪問http://localhost:9090/debug/pprof/，能夠看到：
- {當前協程數量} goroutine
- {當前堆上對象的數量} heap
goroutine 頁面
展示了當前正在運行的所有協程的調用棧，每一塊調用棧的開頭表示 pprof 採樣時有多少個協程處於這個調用棧，如下表示有 4 個協程：
4 @ 0x42ec9c 0x429daa 0x4293a7 0x491b9e 0x491c1d 0x4929ba 0x563772 0x575aad 0x65bef5 0x516a5a 0x51790c 0x517b74 0x5e9fd0 0x5e9ddb 0x656169 0x65d1fc 0x660ffe 0x45d5e1
#\t0x4293a6\tinternal/poll.runtime_pollWait+0x56\t\t/home/rokety/Software/go/src/runtime/netpoll.go:173
#\t0x491b9d\tinternal/poll.(*pollDesc).wait+0xad\t\t/home/rokety/Software/go/src/internal/poll/fd_poll_runtime.go:85
#\t0x491c1c\tinternal/poll.(*pollDesc).waitRead+0x3c\t\t/home/rokety/Software/go/src/internal/poll/fd_poll_runtime.go:90
#\t0x4929b9\tinternal/poll.(*FD).Read+0x189\t\t\t/home/rokety/Software/go/src/internal/poll/fd_unix.go:126
#\t0x563771\tnet.(*netFD).Read+0x51\t\t\t\t/home/rokety/Software/go/src/net/fd_unix.go:202
#\t0x575aac\tnet.(*conn).Read+0x6c\t\t\t\t/home/rokety/Software/go/src/net/net.go:176
#\t0x65bef4\tnet/http.(*connReader).Read+0x104\t\t/home/rokety/Software/go/src/net/http/server.go:753
#\t0x516a59\tbufio.(*Reader).fill+0x119\t\t\t/home/rokety/Software/go/src/bufio/bufio.go:97
#\t0x51790b\tbufio.(*Reader).ReadSlice+0x2b\t\t\t/home/rokety/Software/go/src/bufio/bufio.go:338
#\t0x517b73\tbufio.(*Reader).ReadLine+0x33\t\t\t/home/rokety/Software/go/src/bufio/bufio.go:367
#\t0x5e9fcf\tnet/textproto.(*Reader).readLineSlice+0x6f\t/home/rokety/Software/go/src/net/textproto/reader.go:55
#\t0x5e9dda\tnet/textproto.(*Reader).ReadLine+0x2a\t\t/home/rokety/Software/go/src/net/textproto/reader.go:36
#\t0x656168\tnet/http.readRequest+0x98\t\t\t/home/rokety/Software/go/src/net/http/request.go:925
#\t0x65d1fb\tnet/http.(*conn).readRequest+0x17b\t\t/home/rokety/Software/go/src/net/http/server.go:933
#\t0x660ffd\tnet/http.(*conn).serve+0x50d\t\t\t/home/rokety/Software/go/src/net/http/server.go:1739
heap 頁面
展示了堆內存的詳細信息，頁面底部部分信息字段說明：
- NumGC：程序運行到現在的 gc 執行次數
- PauseNs：是擁有 256 個元素的環形緩衝，用於記錄最近的 256 次 gc 執行的停頓時間（一次 gc 執行可能會有多次停頓，這裡記錄的是一次 gc 執行中總的停頓時間）
- PauseEnd：也是擁有 256 個元素的環形緩衝，用於記錄最近的 256 次 gc 執行時，停頓結束的時間戳（納秒級）（一次 gc 執行可能會有多次停頓，這裡記錄的是最後的一次停頓的結束時間）
- 更多字段含義可以查看：runtime.MemStats[3]
現在開始進行採樣並分析，執行 go tool pprof --seconds 5 http://localhost:9090/debug/pprof/profile，會將採樣結果下載下來，並且打開一個交互界面：
Fetching profile over HTTP from http://localhost:9090/debug/pprof/profile?seconds=5
Please wait... (5s)
Saved profile in /home/rokety/pprof/pprof.main.samples.cpu.002.pb.gz
File: main
Type: cpu
Time: Dec 25, 2017 at 10:26pm (CST)
Duration: 5.12s, Total samples = 8.86s (173.15%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3790ms, 42.78% of 8860ms total
Dropped 198 nodes (cum <= 44.30ms)
Showing top 10 nodes out of 182
flat flat% sum% cum cum%
2070ms 23.36% 23.36% 2170ms 24.49% syscall.Syscall /home/rokety/Software/go/src/syscall/asm_linux_amd64.s
550ms 6.21% 29.57% 560ms 6.32% syscall.Syscall6 /home/rokety/Software/go/src/syscall/asm_linux_amd64.s
200ms 2.26% 31.83% 380ms 4.29% regexp.(*machine).tryBacktrack /home/rokety/Software/go/src/regexp/backtrack.go
200ms 2.26% 34.09% 200ms 2.26% runtime.epollctl /home/rokety/Software/go/src/runtime/sys_linux_amd64.s
150ms 1.69% 35.78% 150ms 1.69% runtime._ExternalCode /home/rokety/Software/go/src/runtime/proc.go
140ms 1.58% 37.36% 140ms 1.58% runtime.memmove /home/rokety/Software/go/src/runtime/memmove_amd64.s
130ms 1.47% 38.83% 620ms 7.00% runtime.mallocgc /home/rokety/Software/go/src/runtime/malloc.go
120ms 1.35% 40.18% 200ms 2.26% runtime.mapassign_faststr /home/rokety/Software/go/src/runtime/hashmap_fast.go
120ms 1.35% 41.53% 120ms 1.35% runtime.usleep /home/rokety/Software/go/src/runtime/sys_linux_amd64.s
110ms 1.24% 42.78% 110ms 1.24% runtime.heapBitsSetType /home/rokety/Software/go/src/runtime/mbitmap.go
(pprof) top -cum
Showing nodes accounting for 2.16s, 24.38% of 8.86s total
Dropped 198 nodes (cum <= 0.04s)
Showing top 10 nodes out of 182
flat flat% sum% cum cum%
0 0% 0% 8.02s 90.52% net/http.(*conn).serve /home/rokety/Software/go/src/net/http/server.go
0.03s 0.34% 0.34% 3.53s 39.84% net/http.(*ServeMux).ServeHTTP /home/rokety/Software/go/src/net/http/server.go
0 0% 0.34% 3.53s 39.84% net/http.serverHandler.ServeHTTP /home/rokety/Software/go/src/net/http/server.go
0 0% 0.34% 3.35s 37.81% github.com/prashantv/go_profiling_talk/handlers.WithStats.func1 /home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/handlers/stats_handler.go
0 0% 0.34% 3.35s 37.81% net/http.HandlerFunc.ServeHTTP /home/rokety/Software/go/src/net/http/server.go
0.01s 0.11% 0.45% 2.38s 26.86% net/http.(*response).finishRequest /home/rokety/Software/go/src/net/http/server.go
2.07s 23.36% 23.81% 2.17s 24.49% syscall.Syscall /home/rokety/Software/go/src/syscall/asm_linux_amd64.s
0.02s 0.23% 24.04% 2.07s 23.36% bufio.(*Writer).Flush /home/rokety/Software/go/src/bufio/bufio.go
0.01s 0.11% 24.15% 1.86s 20.99% github.com/prashantv/go_profiling_talk/handlers.getStatsTags /home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/handlers/stats_handler.go
0.02s 0.23% 24.38% 1.80s 20.32% net/http.(*conn).readRequest /home/rokety/Software/go/src/net/http/server.go
top 默認顯示 10 個佔用 CPU 時間最多的函數，top -cum 則顯示 10 個佔用 CPU 時間（包括其調用的子函數）最多的函數。
使用 web 命令可以在瀏覽器打開一張 SVG 圖，能夠更好地看到函數調用 CPU 佔用情況（web依賴 Graphviz，沒有的話安裝下 sudo apt-get install graphviz）：
圖有點大（點擊上圖可打開 svg 圖片），以如下方塊為例：
- net/http(*ServeMux)ServeHTTP server.go：調用的函數
- 0.03s(0.34%)：表示函數本身執行了 0.03s，佔總採樣時間 8.86s 的 0.34%
- 3.53(39.84%)：表示函數本身執行時間+調用的子函數的執行時間用了 3.53s，佔總採樣時間的 39.84%
還可以使用另外一個工具，來生成火焰圖，~/Software/go-app/bin/go-torch --seconds 5 http://localhost:9090/debug/pprof/profile：
（點擊上圖可打開 svg 圖片），火焰圖怎麼看？首先找與業務邏輯代碼相關的且佔用 CPU 時間最多的函數，可以看到github.com/prashantv/go_profiling_talk/handlers.WithStats.func1用於獲取統計信息的函數佔用了不少 CPU 時間，點擊該函數可以看到其調用棧的更詳細信息：
現在可以看到github.com/prashantv/go_profiling_talk/handlers.getStatsTags->os.Hostname的調用是佔最多 CPU 時間的，看下對應的代碼：
func getStatsTags(r *http.Request) map[string]string {
\tuserBrowser, userOS := parseUserAgent(r.UserAgent())
\tstats := map[string]string{
\t\t"browser": userBrowser,
\t\t"os": userOS,
\t\t"endpoint": filepath.Base(r.URL.Path),
\t}
\thost, err := os.Hostname()
\tif err == nil {
\t\tif idx := strings.IndexByte(host, '.'); idx > 0 {
\t\t\thost = host[:idx]
\t\t}
\t\tstats["host"] = host
\t}
\treturn stats
}
os.Hostname在每次請求都會被調用，然而 hostname 不會變化得很頻繁，所以我們可以改下代碼，對應的commit[4]。
看下修改後的性能如何，增加了 3000+qps：
現在，重新生成火焰圖看下，繼續找與業務邏輯代碼相關的且佔用 CPU 時間最多的函數：
這次我們可以看到github.com/prashantv/go_profiling_talk/stats.addTagsToName->github.com/prashantv/go_profiling_talk/stats.clean佔用許多 CPU 時間，看下對應的代碼：
func addTagsToName(name string, tags map[string]string) string {
\t// The format we want is: host.endpoint.os.browser
\t// if there's no host tag, then we don't use it.
\tvar keyOrder []string
\tif _, ok := tags["host"]; ok {
\t\tkeyOrder = append(keyOrder, "host")
\t}
\tkeyOrder = append(keyOrder, "endpoint", "os", "browser")
\tparts := []string{name}
\tfor _, k := range keyOrder {
\t\tv, ok := tags[k]
\t\tif !ok || v == "" {
\t\t\tparts = append(parts, "no-"+k)
\t\t\tcontinue
\t\t}
\t\tparts = append(parts, clean(v))
\t}
\treturn strings.Join(parts, ".")
}
var specialChars = regexp.MustCompile(`[{}/\\\\:\\s.]`)
// clean takes a string that may contain special characters, and replaces these
// characters with a '-'.
func clean(value string) string {
\treturn specialChars.ReplaceAllString(value, "-")
}
在clean函數中使用了正則替換，將 {}/\\\\:\\s. 字符替換為 -。
我們還可以通過go pprof查看上面兩個函數的執行情況，首先寫好 Benchmark 測試用例，對應的commit[5]，然後執行go test -bench . -benchmem -cpuprofile prof.cpu，該命令會產生 CPU 的分析文件prof.cpu。
執行go tool pprof prof.cpu，然後看下addTagsToName函數的執行情況：
上圖紅框中的 10ms 是指某一次採樣時，addTagsToName正好處於調用棧頂，每採樣一次的時間間隔是 10ms。（When CPU profiling is enabled, the Go program stops about 100 times per second and records a sample consisting of the program counters on the currently executing goroutine’s stack.——Profiling Go Programs[6]）你可以發現列出來的時間全都是 10ms 的整數倍。現在我們可以看出佔用 CPU 時間最多的就是clean函數里的正則替換。
將正則替換改為字符替換，對應的commit
[7]，再次執行 benchmark：
如下圖，從top可以看出紅框中的runtime.*的調用佔用最多 CPU，從list clean也可以看出make()和string()佔用了許多 CPU：
我們還可以看下clean的彙編結果：
(pprof) disasm clean
Total: 2.94s
ROUTINE ======================== _/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.clean
160ms 780ms (flat, cum) 26.53% of Total
\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t……
\t\t\t\t. 340ms 4ee07b: CALL runtime.makeslice(SB) ;_/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.clean reporter.go:61
\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t……
\t\t\t\t. 280ms 4ee119: CALL runtime.slicebytetostring(SB) ;_/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.clean reporter.go:70
\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t……
（……表示省略了部分輸出結果）從彙編結果中可以看出runtime.makeslice和runtime.slicebytetostring佔用的 CPU 時間多，然而這裡並沒有我們能優化的，我們再看下addTagsToName：
append佔用了不少 CPU 時間的，主要由於 slice 的擴容，我們可以看下addTagsToName的彙編確認下：
(pprof) disasm addTagsToName
Total: 2.94s
ROUTINE ======================== _/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.addTagsToName
120ms 2.78s (flat, cum) 94.56% of Total
……
. 870ms 4ede3b: CALL runtime.growslice(SB) ;_/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.addTagsToName reporter.go:52
……
. 200ms 4edf65: CALL runtime.growslice(SB) ;_/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.addTagsToName reporter.go:43
……
. 130ms 4edfb1: CALL runtime.growslice(SB) ;_/home/rokety/Learn/golang/src/github.com/prashantv/go_profiling_talk/stats.addTagsToName reporter.go:41
從addTagsToName的代碼邏輯中可以分析出，我們可以通過 make 創建好需要的 slice 容量，此優化對應的commit[8]，優化後 append 操作佔用的 CPU 時間下降了不少：
addTagsToName返回值是將一個 slice 通過 join 後得到的 string，那麼這裡可以考慮使用bytes.Buffer來代替 slice，看看是否能帶來一些性能提升，此優化對應的commit[9]：
從上圖看出，list addTagsToName性能提升並不明顯，但 Benchmark 的結果可以發現ns/op和allocs/op，以及執行的次數都有所提升，在 Benchmark 這種大壓力執行下，整體性能提升不少。
現在來看還有 2 個 allocs，執行go test -bench . -benchmem -memprofile prof.mem看下內存分析結果：
從上圖可以看到 2 個 allocs，一個在 buffer.go 中，這個我們沒法優化掉，一個在 addTagsToName 中，是給bytes.Buffer分配內存，這個是否可以優化掉呢？Golang 提供了 sync.Pool 可以用來緩存對象，嘗試下是否能夠得到性能提升，對應的代碼修改如下：
var bufPool = sync.Pool{
\tNew: func() interface{} {
\t\treturn &bytes.Buffer{}
\t},
}
func addTagsToName(name string, tags map[string]string) string {
\t// The format we want is: host.endpoint.os.browser
\t// if there's no host tag, then we don't use it.
\tkeyOrder := make([]string, 0, 4)
\tif _, ok := tags["host"]; ok {
\t\tkeyOrder = append(keyOrder, "host")
\t}
\tkeyOrder = append(keyOrder, "endpoint", "os", "browser")
\t buf := bufPool.Get().(*bytes.Buffer)
\t defer bufPool.Put(buf)
\t buf.Reset()
\t//buf := &bytes.Buffer{}
\tbuf.WriteString(name)
\tfor _, k := range keyOrder {
\t\tbuf.WriteByte('.')
\t\tv, ok := tags[k]
\t\tif !ok || v == "" {
\t\t\tbuf.WriteString("no-")
\t\t\tbuf.WriteString(k)
\t\t\tcontinue
\t\t}
\t\twriteClean(buf, v)
\t}
\treturn buf.String()
}
執行下 Benchmark，可以發現ns/op增加了一點，這個其實主要是因為 defer 的執行也會佔用不少 CPU，改為不使用 defer，對比 Benchmark 結果，ns/op下降了一些：
然而，上面的優化（使用 sync.Pool 和不使用 defer）所帶來的性能提升並不明顯，反而增加了代碼的維護成本，所以最終實現的代碼是這樣子的commit[10]。
目前優化就到此結束了，來看下優化後的性能表現如何：
命令總結
1、進行 5 秒鐘的 CPU 性能採樣並打開一個交互界面：go tool pprof -seconds 5 http://localhost:9090/debug/pprof/profile
- topN：顯示 N 個佔用 CPU 時間最多的函數
- topN -cum：顯示 N 個佔用 CPU 時間（包括其調用的子函數）最多的函數
- list regex：顯示與正則 regex 匹配的函數的代碼
- disasm regex：顯示與正則 regex 匹配的函數的彙編代碼
2、進行壓力測試併產生 CPU 和內存分析文件：go test -bench . -benchmem -cpuprofile prof.cpu -memprofile prof.mem
3、打開 CPU 分析文件：go tool pprof prof.cpu
4、打開內存分析文件：go tool pprof -alloc_objects stats.test prof.mem
5、進行 5 秒鐘的 CPU 性能採樣並生成火焰圖：go-torch --seconds 5 http://localhost:9090/debug/pprof/profile
6、從 CPU 分析文件中生成火焰圖：go-torch --binaryname stats.test -b prof.cpu
7、顯示內聯函數，逃逸分析情況：go build -gcflags=-m .
性能分析總結
- 不要過早的優化：Go 提供了非常便捷的方式幫助我們分析代碼，無論是通過本地的壓測還是在生產環境。go-torch 能幫助你找到熱點的函數。
- 減少在熱點路徑上的內存分配：為熱點路徑編寫壓測用例。使用-benchmem 和內存分析找到在哪裡發生了內存分配，並儘量優化掉。一個內存分配意味著一個可能的 GC，GC 會增加請求的延遲。
- 不要害怕查看彙編代碼：有時內存分配和時間消耗不能清晰地從我們的代碼裡看出來，那就嘗試看下彙編結果，通常你能從中找到導致內存分配和時間消耗的函數（例如 runtime.convI2E）。
文中鏈接
[1]Profiling and Optimizing Go: https://www.youtube.com/watch?v=N3PWzBeLX2M
[2]PPT: https://docs.google.com/presentation/d/1n6bse0JifemG7yve0Bb0ZAC-IWhTQjCNAclblnn2ANY/present?slide=id.g39a91bbe9_0264
[3]runtime.MemStats: https://golang.org/pkg/runtime/#MemStats
[4]commit: https://github.com/prashantv/go_profiling_talk/commit/a8c6b0e1cd043df85ccbc57883c6422863176c17
[5]commit: https://github.com/prashantv/go_profiling_talk/commit/b26d6c4672d1fd8f063ab3a4a5fd0589b742cec8
[6]Profiling Go Programs: https://blog.golang.org/profiling-go-programs
[7]commit: https://github.com/prashantv/go_profiling_talk/commit/87fa6d9ae553234169aeac719a67c4d39eca2777
[8]commit: https://github.com/prashantv/go_profiling_talk/commit/9fb6e8db2884b20cb7f5a576f2dc4e36f477af2f
[9]commit: https://github.com/prashantv/go_profiling_talk/commit/a2f0a614abd36b734cb413dc759c4fb21cd6de80
[10]commit: https://github.com/prashantv/go_profiling_talk/commit/02630f1c5bcf2fbdc034eca393ab34071221d1ef
閱讀更多 Go語言中文網 的文章
關鍵字: 軟件 中央處理器 PowerPoint
