【譯】優化Go的模式

mnhkahn發表於2016-10-11
優化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的結果到資料庫，這樣你可以在每一次程式碼提交之後檢視程式碼的效能。

相關文章