[譯] 優化 Go 的模式

之前寫過一篇文章《為什麼 SignalFx metric proxy 通過 Go 語言開發》，這篇文章將會關注以我們的 ingest 服務為例，來講述我們是如何優化 Go 程式碼的。

SingalFx 基於流分析和時間報警序列，例如應用程式指標，可以為時間序列資料的現代應用開發的高階監控平臺（“我的應用程式收到了多少請求？”），還有系統級指標（“我的 Linux 伺服器使用了多少網路流量？”）。我們使用者流量很大並且粒度很高，每次使用者的流量都要先通過我們的 ingest 服務才能訪問其它的 SignalFx 服務。

第一步：啟用 pprof

啥是 pprof？

pprof 是 Go 語言內建的標準方法用來除錯 Go 程式效能。可以通過 HTTP 的方式呼叫 pprof 包，它能提取出來應用程式的 CPU 和記憶體資料，此外還有執行的程式碼行數和內容資訊。

如何啟用 pprof？

你可以通過在你的應用增加一行程式碼 import _ "net/http/pprof"，然後啟動你的應用伺服器，pprof 就算是啟動了。還有一種方式，就是我們在做 SignalFx 的時候，為了在外部控制 pprof，我們附加了一些處理程式，可以用過路由設定暴露出去，程式碼如下：

import "github.com/gorilla/mux"
import "net/http/pprof"
var handler *mux.Router
// ...
handler.PathPrefix("/debug/pprof/profile").HandlerFunc(pprof.Profile)
handler.PathPrefix("/debug/pprof/heap").HandlerFunc(pprof.Heap)

第二步：找到可以優化的程式碼

要執行什麼？

curl http://ingest58:6060/debug/pprof/profile > /tmp/ingest.profile
    go tool pprof ingest /tmp/ingest.profile
    (pprof) top7

這是幹嘛的？

Go 語言包含了一個本地的 pprof 工具來視覺化輸出 pprof 的結果。我們配置的路由/debug/pprof/profile可以收集 30 秒資料。我上面的操作，第一步是儲存輸出到本地檔案，然後執行儲存後的檔案。值得一提的是，最後一個引數可以直接輸入一個 URL 來取代檔案（譯者注：go tool pprof ingest http://ingest58:6060/debug/pprof/profile）。 命令 top7 可以展示消耗 CPU 最好的 7 個函式。

結果

12910ms of 24020ms total (53.75%)
Dropped 481 nodes (cum <= 120.10ms)
Showing top 30 nodes out of 275 (cum >= 160ms)
     flat  flat%   sum%        cum   cum%
   1110ms  4.62%  4.62%     2360ms  9.83%  runtime.mallocgc
    940ms  3.91%  8.53%     1450ms  6.04%  runtime.scanobject
    830ms  3.46% 11.99%      830ms  3.46%  runtime.futex
    800ms  3.33% 15.32%      800ms  3.33%  runtime.mSpan_Sweep.func1
    750ms  3.12% 18.44%      750ms  3.12%  runtime.cmpbody
    720ms  3.00% 21.44%      720ms  3.00%  runtime.xchg
    580ms  2.41% 23.86%      580ms  2.41%  runtime._ExternalCode

為啥是這個結果

我們可以發現，這些函式我們都沒有直接呼叫過。然而，mallocgc、sacnobject還有mSpan_Sweep全部都會導致是垃圾回收的時候 CPU 佔用高。我們可以深入瞭解這些函式，而不是去優化 Go 語言的垃圾回收器本身，更好的優化辦法是我們來優化我們程式碼裡面使用 Go 語言的垃圾回收器的方法。在這個例子中，我們可以優化的是減少在堆上面建立物件。

第三步：探究 GC 的原因

執行啥？

curl http://ingest58:6060/debug/pprof/heap > /tmp/heap.profile
go tool pprof -alloc_objects /tmp/ingest /tmp/heap.profile
(pprof) top3

做了啥？

可以注意到這次下載的 URL 和之前的有點像，但是是以/heap 結尾的。這個將會給我們提供機器上面堆的使用總結的資料。我再一次儲存成檔案使用者後面的比較。引數-alloc_objects 將會視覺化應用程式在執行過程中分配的物件數量。

結果

4964437929 of 7534904879 total (65.89%)
Dropped 541 nodes (cum <= 37674524)
Showing top 10 nodes out of 133 (cum >= 321426216)
     flat  flat%   sum%        cum   cum%
853721355 11.33% 11.33%  859078341 11.40%  github.com/signalfuse/sfxgo/ingest/tsidcache/tsiddiskcache.(*DiskKey).EncodeOld
702927011  9.33% 20.66%  702927011  9.33%  reflect.unsafe_New
624715067  8.29% 28.95%  624715067  8.29%  github.com/signalfuse/sfxgo/ingest/bus/rawbus.(*Partitioner).Partition

啥意思？

可以看出，11.33% 的物件分配都發生在物件DiskKey的函式EncodeOld裡面，我們預期也是這個結果。然而，沒有料到的是 Partition 函式佔用了全部記憶體分配的 8.29%，因為這個函式只是一些基本的計算，我得著重研究一下這個問題。

第四步：找到為什麼 partitioner 使用如此多記憶體的原因

執行啥？

(pprof) list Partitioner.*Partition

做了啥？

這個命令可以列印出來我關注的原始碼行，還有就是函式內部哪些程式碼引起了堆的記憶體申請。這是 pprof 裡面許多命令的其中一個。另一個非常有用的是檢視呼叫方和被呼叫方。可以通過 help 命令檢視完整的幫助並且都試一試。

結果

Total: 11323262665
ROUTINE ======================== github.com/signalfuse/sfxgo/ingest/bus/rawbus.(*Partitioner).Partition in /opt/jenkins/workspace/ingest/gopath/src/github.com/signalfuse/sfxgo/ingest/bus/rawbus/partitioner.go
927405893  927405893 (flat, cum)  8.19% of Total
        .          .     64: if ringSize == 0 {
        .          .     65: return 0, ErrUnsetRingSize
        .          .     66: }
        .          .     67: var b [8]byte
        .          .     68: binary.LittleEndian.PutUint64(b[:], uint64(message.Key.(*partitionPickingKey).tsid))
239971917  239971917     69: logherd.Debug2(log, "key", message.Key, "numP", numPartitions, "Partitioning")
        .          .     70: murmHash := murmur3.Sum32(b[:])
        .          .     71:
        .          .     72: // 34026 => 66
        .          .     73: setBits := uint(16)
        .          .     74: setSize := uint32(1 << setBits)
        .          .     75: shortHash := murmHash & (setSize - 1)
        .          .     76: smallIndex := int32(shortHash) * int32(k.ringSize) / int32(setSize)
687433976  687433976     77: logherd.Debug3(log, "smallIndex", smallIndex, "murmHash", murmHash, "shortHash", shortHash, "Sending to partition")
        .          .     78: return smallIndex, nil
        .          .     79:}
        .          .     80:

啥意思？

這個可以表示 debug 日誌是引起變數從棧逃逸到堆的原因。因為除錯日誌並不是直接需要的，我能夠直接刪掉這些行。但是首先，還是讓我們來確認這個假設。logherd.Debug2函式看起來封裝瞭如下所示，如果日誌級別 debug 沒有符合條件，WithField 物件並不會呼叫。

// Debug2 to logger 2 key/value pairs and message.  Intended to save the mem alloc that WithField creates
func Debug2(l *logrus.Logger, key string, val interface{}, key2 string, val2 interface{}, msg string) {
     if l.Level >= logrus.DebugLevel {
          l.WithField(key, val).WithField(key2, val2).Debug(msg)
     }
}

從 pprof 檢測看起來是傳遞整數到Debug2函式引起的記憶體分配，讓我們進一步確認。

第五步：找到日誌語句引起記憶體分配的原因

執行什麼：

go build -gcflags='-m' . 2>&1 | grep partitioner.go

這個用來幹啥？

通過-m 引數編譯可以讓編譯器列印內容到 stderr。這包括編譯器是否能夠在棧上面分配記憶體還是一定得將變數放到堆上面申請。如果編譯器不能決定一個變數是否在外部繼續被呼叫，他會被 Go 語言放到堆上面。

結果

./partitioner.go:63: &k.ringSize escapes to heap
./partitioner.go:62: leaking param: k
./partitioner.go:70: message.Key escapes to heap
./partitioner.go:62: leaking param content: message
./partitioner.go:70: numPartitions escapes to heap
./partitioner.go:77: smallIndex escapes to heap
./partitioner.go:77: murmHash escapes to heap
./partitioner.go:77: shortHash escapes to heap
./partitioner.go:68: (*Partitioner).Partition b does not escape
./partitioner.go:71: (*Partitioner).Partition b does not escape

注意第 77 行，smallIndex、murmHash還有shortHash全部逃逸到了堆上面。編譯器為短生命週期的變數在堆上面申請了空間，導致我們在對上建立了很多我們並不需要的物件。

第六步：對 partition 函式壓測

寫什麼？

func BenchmarkPartition(b *testing.B) {

     r := rand.New(rand.NewSource(0))

     k := partitionPickingKey{}

     msg := sarama.ProducerMessage {

          Key: &k,

     }

     p := Partitioner{

          ringSize: 1024,

          ringName: "quantizer.ring",

     }

     num_partitions := int32(1024)

     for i := 0; i < b.N; i++ {

          k.tsid = r.Int63()

          part, err := p.Partition(&msg, num_partitions)

          if err != nil {

               panic("Error benchmarking")

          }

          if part < 0 || part >= num_partitions {

               panic("Bench failure")

          }

     }

}

壓測只是簡單的建立了 B.N 個物件，並且在返回的時候做了一個基本的檢查來確認物件不會被簡單的優化掉。我們推薦當程式設計師在優化程式碼之前編寫壓測程式碼來確保你在朝著正確的方向進行。

第七步：對 partition 函式壓測記憶體分配

執行啥？

go test -v -bench . -run=_NONE_ -benchmem BenchmarkPartition

做了啥？

壓測會按照正則匹配符合 “.” 條件的函式，-benchmen 將會追蹤每次迴圈的堆使用平均情況。通過傳遞引數-run=_NONE_，我可以節約一些時間，這樣測試只會執行有 “NONE” 字串的單元測試。換句話說，不下執行任何一個單元測試，只執行全部的壓力測試。

結果

PASS

BenchmarkPartition-8 10000000       202 ns/op      64 B/op       4 allocs/op

意味著啥？

每一次迴圈消耗平均 202ns，最重要的是，每個操作有 4 次物件分配。

第八步：刪掉日誌語句

咋寫？

@@ -66,7 +65,6 @@ func (k *Partitioner) Partition(message *sarama.ProducerMessage, numPartitions i

       }

       var b [8]byte

       binary.LittleEndian.PutUint64(b[:], uint64(message.Key.(*partitionPickingKey).tsid))

-       logherd.Debug2(log, "key", message.Key, "numP", numPartitions, "Partitioning")

       murmHash := murmur3.Sum32(b[:])

       // 34026 => 66

@@ -74,7 +72,6 @@ func (k *Partitioner) Partition(message *sarama.ProducerMessage, numPartitions i

       setSize := uint32(1 << setBits)

       shortHash := murmHash & (setSize - 1)

       smallIndex := int32(shortHash) * int32(k.ringSize) / int32(setSize)

-       logherd.Debug3(log, "smallIndex", smallIndex, "murmHash", murmHash, "shortHash", shortHash, "Sending to partition")

       return smallIndex, nil

}

幹了什麼？

我的修復方式是刪除日誌程式碼。測試期間/除錯期間，我增加了這些除錯程式碼，但是一直沒有刪掉它們。這種情況下，刪掉這些程式碼最簡單。

第九步：重新編譯評估是否變數逃逸到了堆

如何執行？

go build -gcflags='-m' . 2>&1 | grep partitioner.go

結果

./partitioner.go:62: &k.ringSize escapes to heap

./partitioner.go:61: leaking param: k

./partitioner.go:61: (*Partitioner).Partition message does not escape

./partitioner.go:67: (*Partitioner).Partition b does not escape

./partitioner.go:68: (*Partitioner).Partition b does not escape

意味著什麼？

可以發現smallIndex、murmHash和shortHash變數不在有逃逸到堆的訊息。

第十步：重新壓測評估每個操作的記憶體分配情況

如何執行？

go test -v -bench . -run=_NONE_ -benchmem BenchmarkPartition

結果

PASS

BenchmarkPartition-8 30000000        40.5 ns/op       0 B/op       0 allocs/op

ok   github.com/signalfuse/sfxgo/ingest/bus/rawbus 1.267s

啥意思？

注意到每個操作只消耗 40ns，更重要的是，每個操作不再有記憶體分配。因為我是準備來優化堆，這對我來說很重要。

結束語

pprof 是非常有用的工具來剖析 Go 程式碼的效能問題。通過結合 Go 語言內建的壓測工具，你能夠得到關於程式碼改變引起的變化的真正的數字。不幸的是，效能衰退會隨著時間而攀升。下一步，讀者可以練習，儲存 benchmark 的結果到資料庫，這樣你可以在每一次程式碼提交之後檢視程式碼的效能。