這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。Go 語言有一個很強大的內建分析器（profiler），支援CPU、記憶體、協程 與 阻塞/搶佔（block/contention）的分析。## 開啟分析器（profiler）Go 提供了一個低級的分析 API [runtime/pprof](https://golang.org/pkg/runtime/pprof/) ，但如果你在開發一個長期啟動並執行服務，使用更進階的 [net/http/pprof](https://golang.org/pkg/net/http/pprof/) 包會更加便利。你只需要在代碼中加入 `import _ "net/http/pprof"` ，它就會自動註冊所需的 HTTP 處理器（Handler） 。```gopackage mainimport ("net/http"_ "net/http/pprof")func hiHandler(w http.ResponseWriter, r *http.Request) {w.Write([]byte("hi"))}func main() {http.HandleFunc("/", hiHandler)http.ListenAndServe(":8080", nil)}```如果你的 web 應用使用自訂的 URL 路由，你需要手動註冊一些 HTTP 端點（endpoints） 。```gopackage mainimport ("net/http""net/http/pprof")func hiHandler(w http.ResponseWriter, r *http.Request) {w.Write([]byte("hi"))}func main() {r := http.NewServeMux()r.HandleFunc("/", hiHandler)// Register pprof handlersr.HandleFunc("/debug/pprof/", pprof.Index)r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)r.HandleFunc("/debug/pprof/profile", pprof.Profile)r.HandleFunc("/debug/pprof/symbol", pprof.Symbol)r.HandleFunc("/debug/pprof/trace", pprof.Trace)http.ListenAndServe(":8080", r)}```如上代碼那樣，開啟 web 應用，然後使用 pprof 工具：```shellgo tool pprof [binary] http://127.0.0.1:8080/debug/pprof/profile```pprof 的最大的優點之一是它是的效能負載很小，可以在生產環境中使用，不會對 web 請求響應造成明顯的效能消耗。但是在深入挖掘 pprof 之前，我們需要一個真實案例來展示如何在 GO 應用中檢查並解決效能問題。## 案例： Left-pad 微服務假設，你需要開發一個全新的微服務，為輸入的字串添加左填充```shell$ curl "http://127.0.0.1:8080/v1/leftpad/?str=test&len=10&chr=*"{"str":"******test"}```這個服務需要收集基本的指標（metric），如請求的數量與每個請求的回應時間。收集到的所有指標都應該發送到一個指標彙總器（metric aggregator）（例如 [StatsD](https://github.com/etsy/statsd)）除此之外，這個服務需要日誌記錄這個請求的詳細資料，如 URL，IP 位址與 user-agent 。你可以在 Github 上看到這個微服務的初步實現，tag 為 [v1](https://github.com/akrylysov/goprofex/tree/v1)編譯並運行這個應用```shellgo build && ./goprofex```## 效能分析我們將要測試這個微服務每秒可以處理多少個請求，可以使用這個工具 [Apache Benchmark tool](https://httpd.apache.org/docs/2.4/programs/ab.html) :```shellab -k -c 8 -n 100000 "http://127.0.0.1:8080/v1/leftpad/?str=test&len=50&chr=*"# -k Enables HTTP keep-alive# -c Number of concurrent requests# -n Number of total requests to make```測試結果不差，但可以做到更快```shellRequests per second: 22810.15 [#/sec] (mean)Time per request: 0.042 [ms] (mean, across all concurrent requests)```註：上面的測試結果的執行環境：筆記本 MacBook Pro Late 2013 (2.6 GHz Intel Core i5, 8 GB 1600 MHz DDR3, macOS 10.12.3) , Go編譯器版本是1.8 。## CPU 分析（CPU profile）再次執行 Apache benchmark tool ，但這次使用更高的請求數量（1百萬應該足夠了），並同時執行 pprof ：```shellgo tool pprof goprofex http://127.0.0.1:8080/debug/pprof/profile```這個 CPU profiler 預設執行30秒。它使用採樣的方式來確定哪些函數花費了大多數的CPU時間。Go runtime 每10毫秒就停止執行過程並記錄每一個運行中的協程的當前堆棧資訊。當 pprof 進入互動模式，輸入 `top`，這條命令會展示收集樣本中最常出現的函數列表。在我們的案例中，是所有 runtime 與標準庫函數，這不是很有用。```shell(pprof) top63.77s of 69.02s total (92.39%)Dropped 331 nodes (cum <= 0.35s)Showing top 10 nodes out of 78 (cum >= 0.64s) flat flat% sum% cum cum%50.79s 73.59% 73.59% 50.92s 73.78% syscall.Syscall 4.66s 6.75% 80.34% 4.66s 6.75% runtime.kevent 2.65s 3.84% 84.18% 2.65s 3.84% runtime.usleep 1.88s 2.72% 86.90% 1.88s 2.72% runtime.freedefer 1.31s 1.90% 88.80% 1.31s 1.90% runtime.mach_semaphore_signal 1.10s 1.59% 90.39% 1.10s 1.59% runtime.mach_semaphore_wait 0.51s 0.74% 91.13% 0.61s 0.88% log.(*Logger).formatHeader 0.49s 0.71% 91.84% 1.06s 1.54% runtime.mallocgc 0.21s 0.3% 92.15% 0.56s 0.81% runtime.concatstrings 0.17s 0.25% 92.39% 0.64s 0.93% fmt.(*pp).doPrintf```有一個更好的方法來查看進階別的效能概況 —— `web` 命令，它會產生一個熱點（hot spots）的 SVG 映像，可以在瀏覽器中開啟它：從你可以看到這個應用花費了 CPU 大量的時間在 logging、測試報告（metric reporting ）上，以及部分時間在記憶體回收上。使用 `list` 命令可以 inspect 每個函數的詳細代碼，例如 `list leftpad` ：```shell(pprof) list leftpadROUTINE ======================== main.leftpad in /Users/artem/go/src/github.com/akrylysov/goprofex/leftpad.go 20ms 490ms (flat, cum) 0.71% of Total . . 3:func leftpad(s string, length int, char rune) string { . . 4: for len(s) < length { 20ms 490ms 5: s = string(char) + s . . 6: } . . 7: return s . . 8:}```對無懼查看反組譯碼代碼的人而言，可以使用 pprof 的 `disasm` 命令，它有助於查看實際的處理器指令：```shell(pprof) disasm leftpadROUTINE ======================== main.leftpad 20ms 490ms (flat, cum) 0.71% of Total . . 1312ab0: GS MOVQ GS:0x8a0, CX . . 1312ab9: CMPQ 0x10(CX), SP . . 1312abd: JBE 0x1312b5e . . 1312ac3: SUBQ $0x48, SP . . 1312ac7: MOVQ BP, 0x40(SP) . . 1312acc: LEAQ 0x40(SP), BP . . 1312ad1: MOVQ 0x50(SP), AX . . 1312ad6: MOVQ 0x58(SP), CX...```## 函數堆棧分析（Heap profile）執行堆棧分析器（heap profiler）```shellgo tool pprof goprofex http://127.0.0.1:8080/debug/pprof/heap```預設情況下，它顯示當前正在使用的記憶體量：```shell(pprof) top512.17kB of 512.17kB total ( 100%)Dropped 85 nodes (cum <= 2.56kB)Showing top 10 nodes out of 13 (cum >= 512.17kB) flat flat% sum% cum cum% 512.17kB 100% 100% 512.17kB 100% runtime.mapassign 0 0% 100% 512.17kB 100% main.leftpadHandler 0 0% 100% 512.17kB 100% main.timedHandler.func1 0 0% 100% 512.17kB 100% net/http.(*Request).FormValue 0 0% 100% 512.17kB 100% net/http.(*Request).ParseForm 0 0% 100% 512.17kB 100% net/http.(*Request).ParseMultipartForm 0 0% 100% 512.17kB 100% net/http.(*ServeMux).ServeHTTP 0 0% 100% 512.17kB 100% net/http.(*conn).serve 0 0% 100% 512.17kB 100% net/http.HandlerFunc.ServeHTTP 0 0% 100% 512.17kB 100% net/http.serverHandler.ServeHTTP```但是我們更感興趣的是分配的對象的數量，執行 pprof 時使用選項 `-alloc_objects````shellgo tool pprof -alloc_objects goprofex http://127.0.0.1:8080/debug/pprof/heap```幾乎 70% 的對象僅由兩個函數分配 —— `leftpad` 與 `StatsD` ，我們需要更仔細的查看它們：```shell(pprof) top559346486 of 633887751 total (88.24%)Dropped 32 nodes (cum <= 3169438)Showing top 10 nodes out of 46 (cum >= 14866706) flat flat% sum% cum cum% 218124937 34.41% 34.41% 218124937 34.41% main.leftpad 116692715 18.41% 52.82% 218702222 34.50% main.(*StatsD).Send 52326692 8.25% 61.07% 57278218 9.04% fmt.Sprintf 39437390 6.22% 67.30% 39437390 6.22% strconv.FormatFloat 30689052 4.84% 72.14% 30689052 4.84% strings.NewReplacer 29869965 4.71% 76.85% 29968270 4.73% net/textproto.(*Reader).ReadMIMEHeader 20441700 3.22% 80.07% 20441700 3.22% net/url.parseQuery 19071266 3.01% 83.08% 374683692 59.11% main.leftpadHandler 17826063 2.81% 85.90% 558753994 88.15% main.timedHandler.func1 14866706 2.35% 88.24% 14866706 2.35% net/http.Header.clone```還有一些非常有用的調試記憶體問題的選項， ` -inuse_objects` 可以顯示正在使用的對象的數量，`-alloc_space` 可以顯示程式啟動以來分配的多少記憶體。自動記憶體配置很便利，但世上沒有免費的午餐。動態記憶體分配不僅比堆棧分配要慢得多，還會間接地影響效能。你在堆上分配的每一塊記憶體都會增加 GC 的負擔，並且佔用更多的 CPU 資源。要使記憶體回收花費更少的時間，唯一的方法是減少記憶體配置。## 逃逸分析（Escape analysis）無論何時使用 `＆` 運算子來擷取指向變數的指標或使用 `make` 或 `new` 分配新值，它並不一定意味著它被分配在堆上。```gofunc foo(a []string) {fmt.Println(len(a))}func main() {foo(make([]string, 8))}```在上面的例子中， `make([]string, 8)` 是在棧上分配記憶體的。Go 通過 escape analysis 來判斷使用堆而不是棧來分配記憶體是否安全。你可以添加選項 `-gcflags=-m` 來查看逃逸分析（escape analysis）的結果：```go5 type X struct {v int}67 func foo(x *X) {8 fmt.Println(x.v)9 }1011 func main() {12 x := &X{1}13 foo(x)14 }``````shellgo build -gcflags=-m./main.go:7: foo x does not escape./main.go:12: main &X literal does not escape```Go 編譯器足夠智能，可以將一些動態分配轉換為棧分配。但你如果使用介面來處理變數，會導致糟糕的情況。```go// Example 1type Fooer interface {foo(a []string)}type FooerX struct{}func (FooerX) foo(a []string) {fmt.Println(len(a))}func main() {a := make([]string, 8) // make([]string, 8) escapes to heapvar fooer Fooerfooer = FooerX{}fooer.foo(a)}// Example 2func foo(a interface{}) string {return a.(fmt.Stringer).String()}func main() {foo(make([]string, 8)) // make([]string, 8) escapes to heap}```Dmitry Vyukov 的論文 [Go Escape Analysis Flaws](https://docs.google.com/document/d/1CxgUBPlx9iJzkz9JWkb6tIpTe5q32QDmz8l0BouG0Cw/view) 講述了更多的逃逸分析（escape analysis）無法處理的案例。一般來說，對於你不需要再修改資料的小結構體，你應該使用值傳參而不是指標傳參。> 註：對於大結構體，使用指標傳參而不是值傳參（複製整個結構體）的效能消耗更低。 ## 協程分析（Goroutine profile）Goroutine profile 會轉儲協程的呼叫堆疊與運行中的協程數量```shellgo tool pprof goprofex http://127.0.0.1:8080/debug/pprof/goroutine```只有18個活躍中的協程，這是非常小的數字。擁有數千個運行中的協程的情況並不少見，但並不會顯著降低效能。## 阻塞分析（Block profile）阻塞分析會顯示導致阻塞的函數調用，它們使用了同步原語（synchronization primitives），如互斥鎖（mutexes）和 channels 。在執行 block contention profile 之前，你必須設定使用[runtime.SetBlockProfileRate](https://golang.org/pkg/runtime/#SetBlockProfileRate) 設定 profiling rate 。你可以在 `main` 函數或者 `init` 函數中添加這個調用。```shellgo tool pprof goprofex http://127.0.0.1:8080/debug/pprof/block````timedHandler` 與 `leftpadHandler` 花費了大量的時間來等待 `log.Printf` 中的互斥鎖。導致這個結果的原因是 `log` package 的實現使用了互斥鎖來對多個協程共用的檔案進行同步訪問（synchronize access）。## 指標（Benchmarking）正如我們之前注意的，在這個案例的最大的幾個效能殺手是 `log` package ，`leftpad` 與 `StatsD.Send` 函數。現在我們找到了效能瓶頸，但是在最佳化代碼之前，我們需要一個可重複的方法來對我們關注的代碼進行效能測試。Go 的 [testing](https://golang.org/pkg/testing/) package 包含了這樣的一個機制。你需要在測試檔案中建立一個函數，以 `func BenchmarkXxx(*testing.B)` 的格式。```gofunc BenchmarkStatsD(b *testing.B) {statsd := StatsD{Namespace: "namespace",SampleRate: 0.5,}for i := 0; i < b.N; i++ {statsd.Incr("test")}}```也可以使用 [net/http/httptest](https://golang.org/pkg/net/http/httptest/) 對這整個 HTTP 程式進行基準測試：```gofunc BenchmarkLeftpadHandler(b *testing.B) {r := httptest.NewRequest("GET", "/v1/leftpad/?str=test&len=50&chr=*", nil)for i := 0; i < b.N; i++ {w := httptest.NewRecorder()leftpadHandler(w, r)}}```執行基準測試：```shellgo test -bench=. -benchmem```它會顯示每次迭代需要的時間量，以及 記憶體/分配數量 （amount of memory/number of allocations）：```BenchmarkTimedHandler-4 200000 6511 ns/op 1621 B/op 41 allocs/opBenchmarkLeftpadHandler-4 200000 10546 ns/op 3297 B/op 75 allocs/opBenchmarkLeftpad10-4 5000000 339 ns/op 64 B/op 6 allocs/opBenchmarkLeftpad50-4 500000 3079 ns/op 1568 B/op 46 allocs/opBenchmarkStatsD-4 1000000 1516 ns/op 560 B/op 15 allocs/op```## 最佳化效能### Logging讓應用運行更快，一個很好又不是經常管用的方法是，讓它執行更少的工作。除了 debug 的目的之外，這行代碼 `log.Printf("%s request took %v", name, elapsed)` 在 web service 中不需要。所有非必要的 logs 應該在生產環境中被移除代碼或者關閉功能。可以使用分級日誌（a leveled logger）來解決這個問題，比如這些很棒的 [日誌工具庫（logging libraries）](https://github.com/avelino/awesome-go#logging)關於打日誌或者其他一般的 I/O 操作，另一個重要的事情是儘可能使用有緩衝的輸入輸出（buffered input/output），這樣可以減少系統調用的次數。通常，並不是每個 logger 調用都需要立即寫入檔案 —— 使用 [bufio](https://golang.org/pkg/bufio/) package 來實現 buffered I/O 。我們可以使用 `bufio.NewWriter` 或者 `bufio.NewWriterSize` 來簡單地封裝 `io.Writer` 對象，再傳遞給 logger ：```golog.SetOutput(bufio.NewWriterSize(f, 1024*16))```### 左填充（leftpad）再看一遍 `leftpad` 函數```gofunc leftpad(s string, length int, char rune) string {for len(s) < length {s = string(char) + s}return s}```在每一個迴圈中連接字串的做法並不高效，因為每一次迴圈迭代都會分配一個新的字串（反覆分配記憶體空間）。有一種更好的方法來構建字串，使用 [bytes.Buffer](https://golang.org/pkg/bytes/#Buffer) ：```gofunc leftpad(s string, length int, char rune) string {buf := bytes.Buffer{}for i := 0; i < length-len(s); i++ {buf.WriteRune(char)}buf.WriteString(s)return buf.String()}```另外，我們還可以使用 [string.Repeat](https://golang.org/pkg/strings/#Repeat) ，使代碼更加簡潔：```gofunc leftpad(s string, length int, char rune) string {if len(s) < length {return strings.Repeat(string(char), length-len(s)) + s}return s}```### StatsD client接下來需要最佳化的代碼是 `StatsD.Send` 函數：```gofunc (s *StatsD) Send(stat string, kind string, delta float64) {buf := fmt.Sprintf("%s.", s.Namespace)trimmedStat := strings.NewReplacer(":", "_", "|", "_", "@", "_").Replace(stat)buf += fmt.Sprintf("%s:%s|%s", trimmedStat, delta, kind)if s.SampleRate != 0 && s.SampleRate < 1 {buf += fmt.Sprintf("|@%s", strconv.FormatFloat(s.SampleRate, 'f', -1, 64))}ioutil.Discard.Write([]byte(buf)) // TODO: Write to a socket}```以下是有一些可能的值得改進的地方：- `Sprintf` 對字串格式化非常便利，它效能表現很好，除非你每秒調用它幾千次。不過，它把輸入參數進行字串格式化的時候會消耗 CPU 時間，而且每次調用都會分配一個新的字串。為了更好的效能最佳化，我們可以使用 `bytes.Buffer` + `Buffer.WriteString/Buffer.WriteByte` 來替換它。- 這個函數不需要每一次都建立一個新的 `Replacer` 執行個體，它可以聲明為全域變數，或者作為 `StatsD` 結構體的一部分。- 用 `strconv.AppendFloat` 替換 `strconv.FormatFloat` ，並且使用堆棧上分配的 buffer 來傳遞變數，防止額外的堆分配。```gofunc (s *StatsD) Send(stat string, kind string, delta float64) {buf := bytes.Buffer{}buf.WriteString(s.Namespace)buf.WriteByte('.')buf.WriteString(reservedReplacer.Replace(stat))buf.WriteByte(':')buf.Write(strconv.AppendFloat(make([]byte, 0, 24), delta, 'f', -1, 64))buf.WriteByte('|')buf.WriteString(kind)if s.SampleRate != 0 && s.SampleRate < 1 {buf.WriteString("|@")buf.Write(strconv.AppendFloat(make([]byte, 0, 24), s.SampleRate, 'f', -1, 64))}buf.WriteTo(ioutil.Discard) // TODO: Write to a socket}```這樣做，將分配數量（number of allocations）從14減少到1個，並且使 `Send` 運行快了4倍。```BenchmarkStatsD-4 5000000 381 ns/op 112 B/op 1 allocs/op```## 測試最佳化結果做了所有最佳化之後，基準測試顯示出非常好的效能提升：```benchmark old ns/op new ns/op deltaBenchmarkTimedHandler-4 6511 1181 -81.86%BenchmarkLeftpadHandler-4 10546 3337 -68.36%BenchmarkLeftpad10-4 339 136 -59.88%BenchmarkLeftpad50-4 3079 201 -93.47%BenchmarkStatsD-4 1516 381 -74.87%benchmark old allocs new allocs deltaBenchmarkTimedHandler-4 41 5 -87.80%BenchmarkLeftpadHandler-4 75 18 -76.00%BenchmarkLeftpad10-4 6 3 -50.00%BenchmarkLeftpad50-4 46 3 -93.48%BenchmarkStatsD-4 15 1 -93.33%benchmark old bytes new bytes deltaBenchmarkTimedHandler-4 1621 448 -72.36%BenchmarkLeftpadHandler-4 3297 1416 -57.05%BenchmarkLeftpad10-4 64 24 -62.50%BenchmarkLeftpad50-4 1568 160 -89.80%BenchmarkStatsD-4 560 112 -80.00%```注: 作者使用 [benchcmp](https://godoc.org/golang.org/x/tools/cmd/benchcmp) 來對比結果：再一次運行 `ab````Requests per second: 32619.54 [#/sec] (mean)Time per request: 0.030 [ms] (mean, across all concurrent requests)```這個 web 服務現在可以每秒多處理10000個請求！ ## 最佳化技巧- 避免不必要的 heap 記憶體配置。- 對於不大的結構體，值傳參比指標傳參更好。- 如果你事Crowdsourced Security Testing道長度，最好提前分配 maps 或者 slice 的記憶體。- 生產環境下，非必要情況不打日誌。- 如果你要頻繁進行連續的讀寫，請使用緩衝讀寫（buffered I/O）- 如果你的應用廣泛使用 JSON，請考慮使用解析器/序列化器（parser/serializer generators）（作者個人更喜歡 [easyjson](https://github.com/mailru/easyjson)）- 在主要路徑上的每一個操作都很關鍵（Every operation matters in a hot path）## 結論有時候，效能瓶頸可能不是你預想那樣，理解應用程式真實效能的最好途徑是認真分析它。你可以在 [Github](https://github.com/akrylysov/goprofex) 上找到本案例的完整的原始碼，初始版本 tag 為 v1，最佳化版本 tag 為 v2 。比較這兩個版本的[傳送門](https://github.com/akrylysov/goprofex/compare/v1...v2) 。> 作者並非以英語為母語，並且他在努力提高英語水平，如果原文有表達問題或者語法錯誤，請糾正他。
via: http://artem.krylysov.com/blog/2017/03/13/profiling-and-optimizing-go-web-applications/
作者：Artem Krylsov 譯者：lightfish-zhang 校對：Unknwon
本文由 GCTT 原創編譯，Go語言中文網 榮譽推出
本文由 GCTT 原創翻譯，Go語言中文網 首發。也想加入譯者行列，為開源做一些自己的貢獻嗎？歡迎加入 GCTT！
翻譯工作和譯文發表僅用於學習和交流目的，翻譯工作遵照 CC-BY-NC-SA 協議規定，如果我們的工作有侵犯到您的權益，請及時聯絡我們。
歡迎遵照 CC-BY-NC-SA 協議規定 轉載，敬請在本文中標註並保留原文/譯文連結和作者/譯者等資訊。
文章僅代表作者的知識和看法，如有不同觀點，請樓下排隊吐槽
734 次點擊 ∙ 1 贊
