剖析 | Go 语言圣经中文版

11.5. 剖析

測量基準對於衡量特定操作的性能是有幫助的, 但是, 當我們視圖讓程序跑的更快的時候, 我們通常併不知道從哪里開始優化. 每個碼農都應該知道 Donald Knuth 在1974年的 ‘‘Structured Programming with go to Statements’’ 上所説的格言. 雖然經常被解讀爲不重視性能的意思, 但是從原文我們可以看到不同的含義:

毫無疑問, 效率會導致各種濫用. 程序員需要浪費大量的時間思考, 或者擔心, 被部分程序的速度所榦擾, 實際上這些嚐試提陞效率的行爲可能産生強烈的負面影響, 特别是當調試和維護的時候. 我們不應該過度糾結於細節的優化, 應該説約97%的場景: 過早的優化是萬惡之源.

我們當然不應該放棄那關鍵的3%的機會. 一個好的程序員不會因爲這個理由而滿足, 他們會明智地觀察和識别哪些是關鍵的代碼; 但是隻有在關鍵代碼已經被確認的前提下才會進行優化. 對於判斷哪些部分是關鍵代碼是經常容易犯經驗性錯誤的地方, 因此程序員普通使用的測量工具, 使得他們的直覺很不靠譜.

當我們想仔細觀察我們程序的運行速度的時候, 最好的技術是如何識别關鍵代碼. 自動化的剖析技術是基於程序執行期間一些抽樣數據, 然後推斷後面的執行狀態; 最終産生一個運行時間的統計數據文件.

Go語言支持多種類型的剖析性能分析, 每一種關註不同的方面, 但它們都涉及到每個采樣記録的感興趣的一繫列事件消息, 每個事件都包含函數調用時函數調用堆棧的信息. 內建的 go test 工具對幾種分析方式都提供了支持.

CPU分析文件標識了函數執行時所需要的CPU時間. 當前運行的繫統線程在每隔幾毫秒都會遇到操作繫統的中斷事件, 每次中斷時都會記録一個分析文件然後恢複正常的運行.

堆分析則記録了程序的內存使用情況. 每個內存分配操作都會觸發內部平均內存分配例程, 每個 512KB 的內存申請都會觸發一個事件.

阻塞分析則記録了goroutine最大的阻塞操作, 例如繫統調用, 管道發送和接收, 還有獲取鎖等. 分析庫會記録每個goroutine被阻塞時的相關操作.

在測試環境下隻需要一個標誌參數就可以生成各種分析文件. 當一次使用多個標誌參數時需要當心, 因爲分析操作本身也可能會影像程序的運行.

$ go test -cpuprofile=cpu.out 
$ go test -blockprofile=block.out 
$ go test -memprofile=mem.out

對於一些非測試程序也很容易支持分析的特性, 具體的實現方式和程序是短時間運行的小工具還是長時間運行的服務會有很大不同, 因此Go的runtim運行時包提供了程序運行時控製分析特性的接口.

一旦我們已經收集到了用於分析的采樣數據, 我們就可以使用 pprof 據來分析這些數據. 這是Go工具箱自帶的一個工具, 但併不是一個日常工具, 它對應 go tool pprof 命令. 該命令有許多特性和選項, 但是最重要的有兩個, 就是生成這個概要文件的可執行程序和對於的分析日誌文件.

爲了提高分析效率和減少空間, 分析日誌本身併不包含函數的名字; 它隻包含函數對應的地址. 也就是説pprof需要和分析日誌對於的可執行程序. 雖然 go test 命令通常會丟棄臨時用的測試程序, 但是在啟用分析的時候會將測試程序保存爲 foo.test 文件, 其中 foo 部分對於測試包的名字.

下面的命令演示了如何生成一個CPU分析文件. 我們選擇 net/http 包的一個基準測試. 通常是基於一個已經確定了是關鍵代碼的部分進行基準測試. 基準測試會默認包含單元測試, 這里我們用 -run=NONE 禁止單元測試.

$ go test -run=NONE -bench=ClientServerParallelTLS64 \
    -cpuprofile=cpu.log net/http
 PASS
 BenchmarkClientServerParallelTLS64-8  1000
    3141325 ns/op  143010 B/op  1747 allocs/op 
ok       net/http       3.395s

$ go tool pprof -text -nodecount=10 ./http.test cpu.log
2570ms of 3590ms total (71.59%)
Dropped 129 nodes (cum <= 17.95ms)
Showing top 10 nodes out of 166 (cum >= 60ms)
    flat  flat%   sum%     cum   cum%
  1730ms 48.19% 48.19%  1750ms 48.75%  crypto/elliptic.p256ReduceDegree
   230ms  6.41% 54.60%   250ms  6.96%  crypto/elliptic.p256Diff
   120ms  3.34% 57.94%   120ms  3.34%  math/big.addMulVVW
   110ms  3.06% 61.00%   110ms  3.06%  syscall.Syscall 
    90ms  2.51% 63.51%  1130ms 31.48%  crypto/elliptic.p256Square
    70ms  1.95% 65.46%   120ms  3.34%  runtime.scanobject
    60ms  1.67% 67.13%   830ms 23.12%  crypto/elliptic.p256Mul
    60ms  1.67% 68.80%   190ms  5.29%  math/big.nat.montgomery
    50ms  1.39% 70.19%    50ms  1.39%  crypto/elliptic.p256ReduceCarry
    50ms  1.39% 71.59%    60ms  1.67%  crypto/elliptic.p256Sum

參數 -text 標誌參數用於指定輸出格式, 在這里每行是一個函數, 根據使用CPU的時間來排序. 其中 -nodecount=10 標誌參數限製了隻輸出前10行的結果. 對於嚴重的性能問題, 這個文本格式基本可以幫助査明原因了.

這個概要文件告訴我們, HTTPS基準測試中 crypto/elliptic.p256ReduceDegree 函數占用了將近一般的CPU資源. 相比之下, 如果一個概要文件中主要是runtime包的內存分配的函數, 那麽減少內存消耗可能是一個值得嚐試的優化策略.

對於一些更微妙的問題, 你可能需要使用 pprof 的圖形顯示功能. 這個需要安裝 GraphViz 工具, 可以從 www.graphviz.org 下載. 參數 -web 用於生成一個有向圖文件, 包含CPU的使用和最特點的函數等信息.

這一節我們隻是簡單看了下Go語言的分析據工具. 如果想了解更多, 可以閲讀 Go官方博客的 ‘‘Proﬁling Go Programs’’ 一文.