原文連接: https://github.com/sxs2473/go...
本文使用 Creative Commons Attribution-ShareAlike 4.0 International 協議進行受權許可。
在先前的部分,咱們研究了對單個函數的基準測試,當您提早知道瓶頸在哪裏時,這是很是有用的。然而,你常常會發現本身處於提問的位置node
爲何這個程序要運行這麼長時間?
剖析整個程序,這對於回答諸如此類的高級問題很是有用。在本節中,咱們將使用Go內置的分析工具從內部研究程序的操做。git
咱們今天要講的第一個工具是 pprof 。 pprof 來自於 Google Perf Tools ,自最先的公開發布以來,已經集成到 Go 運行時中。github
pprof
由兩部分組成:golang
runtime/pprof
每一個 Go 程序都內置的包go
toolpprof
用於解析 profile 文件pprof 支持好幾種類型的分析,咱們今天將討論其中的三種:web
CPU 分析是最多見的類型,也是最明顯的。數組
當啓用 CPU 分析時,運行時將每 10ms 中斷一次,並記錄當前運行的 goroutines 的棧跟蹤。網絡
一旦分析文件完成,咱們就能夠解析它以肯定運行時間最長的代碼路徑。併發
函數在分析文件中出現的次數越多,代碼路徑佔總運行時間的百分比就越多。app
在進行堆分配時,內存分析會記錄調用棧跟蹤dom
棧分配被認爲是無成本的,而且在內存 profile 中不被追蹤
內存分析,就像 CPU 分析是基於樣本的同樣,默認狀況下,每 1000 個分配中有 1 個內存分析樣本。這個速率是能夠改變的。
因爲內存分析是基於樣本的,而且由於它也跟蹤尚沒被使用的分配,所以使用內存分析來肯定應用程序的總內存使用量是很困難的。
我的想法: 我不認爲內存分析對查找內存泄漏有用。有更好的方法來肯定應用程序使用了多少內存。咱們將在之後的文章中討論這些。
阻塞分析很是獨特。
阻塞 profile 和 CPU profile 很是相似,但它記錄了 goroutine 等待共享資源所花費的時間。
這對於肯定應用程序中的併發瓶頸很是有用。
阻塞分析能夠向你展現大量 goroutine 什麼時候能夠取得進展可是被阻塞了。包括:
Lock
一個已經被另外一個 goroutine 鎖定的 sync.Mutex
阻塞分析是一個很是專業的工具,在你認爲已經消除了全部 CPU 和內存使用瓶頸以前,不該該使用它。
互斥鎖分析與阻塞分析相似,但只關注互斥鎖競爭致使延遲的操做。
profile 記錄是有成本的
profile 分析對程序性能有一種適度但可衡量的影響, 尤爲是在增長內存分析採樣率的狀況下。
大多數工具不會阻止你同時啓用多個 profile 。
但仍是不要一次啓用多個 profile 。
若是你同時啓用多個 profile,他們將觀察本身的互動並拋棄你的結果。
Go 運行時的分析接口存在於 runtime/pprof
包中。 runtime/pprof
是一個很是低級的工具,因爲歷史緣由,不一樣類型 profile 的接口並不統一。
正如咱們在前一節中所看到的,pprof 分析工具已經構建到 testing
包中,但有時,在testing.B
基準測試的上下文中放置您想要分析的代碼是不方便或困難的,而且必須直接使用runtime/pprof
API。
這裏有一個 small package,便於更容易地分析現有的程序。
import "github.com/pkg/profile" func main() { defer profile.Start().Stop() ... }
咱們將在本節中使用這個 profile 包。晚些時候,咱們將直接使用runtime/pprof
接口。
解析使用 go pprof
子命令:
go tool pprof /path/to/your/profile
注意 : 若是你已經使用 Go 一段時間了,你可能會被告知pprof
有兩個參數。從 Go 1.9 開始,profile 文件包含展現 profile 所需的全部信息。你再也不須要生成 profile 的二進制文件了。 🎉
咱們寫一個程序來計算單詞數量:
package main import ( "fmt" "io" "log" "os" "unicode" ) func readbyte(r io.Reader) (rune, error) { var buf [1]byte _, err := r.Read(buf[:]) return rune(buf[0]), err } func main() { f, err := os.Open(os.Args[1]) if err != nil { log.Fatalf("could not open file %q: %v", os.Args[1], err) } words := 0 inword := false for { r, err := readbyte(f) if err == io.EOF { break } if err != nil { log.Fatalf("could not read file %q: %v", os.Args[1], err) } if unicode.IsSpace(r) && inword { words++ inword = false } inword = unicode.IsLetter(r) } fmt.Printf("%q: %d words\n", os.Args[1], words) }
讓咱們看看赫爾曼·梅爾維爾的經典《白鯨記》 (源自古騰堡計劃)中有多少單詞。
% time go run main.go moby.txt "moby.txt": 181275 words real 0m2.110s user 0m1.264s sys 0m0.944s
來和 unix 系統的 wc -w
作一個比較
% time wc -w moby.txt 215829 moby.txt real 0m0.012s user 0m0.009s sys 0m0.002s
結果不同。wc 給出的字數高出 19% 左右,由於它計算一個詞的規則與個人例子不一樣。這並不重要——兩個程序都將整個文件做爲輸入,並在一次傳遞中計算從單詞到非單詞的轉換次數。
讓咱們使用 pprof 調查這些程序爲什麼具備不一樣的運行時間。
首先,編輯 main.go
並開啓 profile
... "github.com/pkg/profile" ) func main() { defer profile.Start().Stop() ...
如今,當咱們的程序運行起來時,會建立一個cpu.pprof
文件
% go run main.go moby.txt 2018/08/25 14:09:01 profile: cpu profiling enabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof "moby.txt": 181275 words 2018/08/25 14:09:03 profile: cpu profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof
如今咱們可用用 go tool pprof
來分析它
% go tool pprof /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof Type: cpu Time: Aug 25, 2018 at 2:09pm (AEST) Duration: 2.05s, Total samples = 1.36s (66.29%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 1.42s, 100% of 1.42s total flat flat% sum% cum cum% 1.41s 99.30% 99.30% 1.41s 99.30% syscall.Syscall 0.01s 0.7% 100% 1.42s 100% main.readbyte 0 0% 100% 1.41s 99.30% internal/poll.(*FD).Read 0 0% 100% 1.42s 100% main.main 0 0% 100% 1.41s 99.30% os.(*File).Read 0 0% 100% 1.41s 99.30% os.(*File).read 0 0% 100% 1.42s 100% runtime.main 0 0% 100% 1.41s 99.30% syscall.Read 0 0% 100% 1.41s 99.30% syscall.read
top
命令從降序展現了函數的調用時間。 咱們能夠看到在 syscall.Syscall
上花費了 99% 的時間, 和 main.readbyte
花費了不多的一部分。
咱們還可使用web命令可視化這個調用。這將從 profile 數據生成有向圖。它實際使用來自 Graphviz 的dot
命令。
在圖中,消耗 CPU 時間最多的盒子是最大的 -- 咱們看到的sys call.Syscall
佔用了總程序運行時間的 99.3%。通往syscall.Syscall
的一串盒子表明它的直接調用者 -- 若是多個路徑收斂於同一個函數,則表示有多個調用者。箭頭旁邊的數字表示運行所花費的時間。咱們從 main.readbyte
開始看,一直到最後,佔用都接近0。
咱們程序跑慢不是由於 Go 的 syscall.Syscall
。由於系統調用原本就慢。
每次調用readbyte
都會產生一個緩衝區大小爲1的syscall.Read
。所以,咱們程序執行的系統調用數等於輸入的大小。在 pprof 圖中咱們能夠看到,讀取輸入決定了其餘一切。
func main() { f, err := os.Open(os.Args[1]) if err != nil { log.Fatalf("could not open file %q: %v", os.Args[1], err) } b := bufio.NewReader(f) words := 0 inword := false for { r, err := readbyte(b) if err == io.EOF { break } if err != nil { log.Fatalf("could not read file %q: %v", os.Args[1], err) } if unicode.IsSpace(r) && inword { words++ inword = false } inword = unicode.IsLetter(r) } fmt.Printf("%q: %d words\n", os.Args[1], words) }
這樣咱們能夠經過在輸入文件和readbyte
之間插入bufio.Reader
來提高性能。
words
profile 還告訴了咱們,readbyte
函數內部分配了一些東西。咱們可使用 pprof 進行研究。
defer profile.Start(profile.MemProfile).Stop()
而後正常運行程序
% go run main2.go moby.txt 2018/08/25 14:41:15 profile: memory profiling enabled (rate 4096), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof "moby.txt": 181275 words 2018/08/25 14:41:15 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof
正如咱們所懷疑的那樣,分配來自 readbyte
-- 這並不複雜,只有三行代碼:
func readbyte(r io.Reader) (rune, error) { var buf [1]byte // allocation is here _, err := r.Read(buf[:]) return rune(buf[0]), err }
咱們將在下一節詳細討論爲何會發生這種狀況,但目前咱們看到的是,每一個對readbyte
的調用都在分配一個新的1字節長的數組,而這個數組正在堆上分配。
內存分析有兩種選擇,以 go tool pprof
工具的標識命名:
-alloc_objects
報告每次分配時的所在的地方-inuse_objects
報告被使用的地方,能夠在 profile 文件的末尾找到爲了說明這一點,這裏有一個設計好的程序,它將以一種受控的方式分配一些內存。
// ensure y is live beyond the end of main. var y []byte func main() { defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop() y = allocate(100000) runtime.GC() } // allocate allocates count byte slices and returns the first slice allocated. func allocate(count int) []byte { var x [][]byte for i := 0; i < count; i++ { x = append(x, makeByteSlice()) } return x[0] } // makeByteSlice returns a byte slice of a random length in the range [0, 16384). func makeByteSlice() []byte { return make([]byte, rand.Intn(1<<14)) }
該程序使用 profile 包進行標註,咱們將內存採集速率設置爲1——也就是說,每一個分配都記錄堆棧跟蹤。這大大下降了程序的速度,但你很快就會明白爲何。
% go run main.go 2018/08/25 15:22:05 profile: memory profiling enabled (rate 1), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof 2018/08/25 15:22:05 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof
讓咱們看一下分配對象的圖,這是默認值,並顯示了致使 profile 文件中每一個對象分配的調用圖。
% go tool pprof -web -alloc_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof
不足爲奇的是超過 99% 的分配都是在 makeByteSlice
內部進行的。如今讓咱們 換用-inuse_objects
查看 profile
% go tool pprof -web -inuse_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof
咱們看到的不是在 profile 期間分配的對象,而是在 profile 獲取時仍在使用的對象——這忽略了垃圾收集器回收的對象的堆棧跟蹤。
咱們將展現最後一種分析 - 阻塞分析。咱們使用 net/http
包中ClientServer
的基準測試。
% go test -run=XXX -bench=ClientServer$ -blockprofile=/tmp/block.p net/http % go tool pprof -web /tmp/block.p
Go 1.7 已經發布,而且與 amd64 的新編譯器一塊兒,編譯器如今默認啓用幀指針。
幀指針是一個始終指向當前棧幀頂部的寄存器。
它支持使用 gdb(1)
和 perf(1)
等工具解析 Go 調用棧
詳情能夠參考下面的擴展閱讀