記一次golang gc最佳化過程

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

我們使用golang編寫的線上服務，通常會設定一個golang runtime指標監控，包括goroutine num、gc num、gc pause 等等。最近的一次上線，發現 gc 相關的指標出現異常，gc num 和 gc pause 大幅升高。由於 golang 的 gc 是 stop the world 來做， gc 過多會搶佔程式的正常執行時間，甚至影響對外提供的服務，因此暫停了上線，準備先把 gc 的問題修複下。

出問題時的 gc 監控如下：

image.png

其中藍色曲線表示 gc num，黃色曲線表示 gc pause（單位ms），兩個指標都是30s的累計資料。可以看到每30s的pause達到了秒層級。

登入到線上機器，通過 go tool pprof --alloc_objects http://localhost:xxxx/debug/pprof/heap 命令，查看對象分配的採樣記錄。發現比較大頭的有reflect.Value、encoding/json、fmt.Sprint。考慮到程式中為了更好地做抽象，使用了反射操作，而 reflect.Value 會將對象拷貝並分配到堆上，程式中的對象都是訊息體，有的訊息體會超大，因此會分配較多的堆記憶體。對程式做了一版最佳化，去掉這個反射邏輯，改為switch case，重新上線，發現 gc 略有下降，但效果還是不夠。

image.png

繼續做 profile，已經沒有了 reflect.Value，於是只能再從另外兩項入手。

這個程式是一個老程式的重構版，當時為了做diff測試，加了大量的日誌，包括debug日誌，甚至有些用來做diff的日誌是marshal成json的。我們用的日誌庫沒有做特殊處理，每條日誌都會先調用 fmt.Sprint，這個函數會把對象分配到堆上。針對上述情況，做了大量的日誌刪減，gc 略有下降但效果不夠。

image.png

繼續做效能分析，發現gc大頭還是json相關操作。這個應用程式的主要功能就是處理json格式傳入的訊息，因此除非從 json 庫著手改善，否則似乎解決不了問題。BTW，在處理的諸多訊息中，有一類訊息體佔用位元組數巨大，是其他訊息的十倍以上。嘗試取消訂閱這類訊息，發現gc立即好轉，恢複到正常水平。不過，這條路徑走不通。

分析本程式的特點，它基於訊息觸發的模式，每次訊息到來就會處理，處理就會有堆對象產生。golang 的 gc 時機是根據當前與上次的 heap size 的比例來決定，預設情況下是100，即新增一倍就會觸發。嘗試把這個比例調大 export GOGC=400，試圖降低 gc 觸發頻率，發現效果還是不錯的，兩個指標均有明顯下降，其他指標無明顯異常，暫時先這樣解決，以後有餘力再做程式層面最佳化。

image.png