Golang 效能工具案例

Chung-chun Lo
Skyler Record
Published in
6 min readMay 31, 2023

最近在寫了一個有關檔案上傳的服務並且壓測了一下,在壓測的過程中發現每當 request 數量上來的時候 Gin 在 ParseMultipartForm 的時間就會拉的異常的長。

從下面 trace 的圖來看就知道光是花在 ParseMultipartForm 就至少 46s !!

上網查了一下似乎也有人遇到類似的問題,但都沒有一個明確的說明原因或是解法。

效能問題必須解決所以開始看了一遍 Gin 有關 ParseMultipartForm 的部分,但看來看去覺得 Gin 也只是把 Golang net/http 的內容簡單的在封裝一層而已,而 Golang 本身在這部分應該不太可能會有那麼誇張的效能問題不然社群上早就會有一堆人在提報 issue 了。

原因到底出在哪呢?

這時候想到了 pprof 雖然之前就知道這東西,但其實一直沒有使用它的場景所以一直沒用過,所以決定就來使用 pprof 來確認到底是哪一段的花費了大量的時間。

下圖是 pprof 抓取 CPU 的結果由於是公司的服務所以大部分都遮蔽了,但還是看得出來其實 MultipartForm 並沒有花太多 CPU 的時間,為何跟 Trace 顯示的不同?

到底為什麼 pprof 的值會跟 trace 差了那麼多,查了一下發現 pprof 對於消耗時間的計算是實際 CPU 所消耗的時間。

這段時間並不包含網路io 、lock 等等的也就是所謂 off cpu 的時間,要觀察 off cpu 的時間要使用 fg prof 其結果如下。

可以看到在抓取 10s 的區間內 multipartForm 總共就佔了 365.27s,搭配先前 pprof 的結果實際在 multipartForm cpu 所花的時間才一秒多。

代表有大部分的時間都消耗在了其他的地方!!

這時候又利用了另一個分析工具 go trace ,go trace 主要是用來觀察 groutine 做了哪些操作以及 lock 、執行/阻塞時間等等的。

使用方式如果是持續在進行中的服務,只要有使用 pprof 的話可以透過以下方式取得檔案。

curl https://{host}/debug/pprof/trace?seconds=10

取得檔案後再利用 go tool 就可以開啟了

go tool trace {file path}

開啟 trace web 後觀察了 Goroutine analysis 內的 runHandler 並採用
Sync block 排序發現許多的 goroutine 光是在 Sync block 就佔了快 10s

點進去其中一個 goroutine 後會發現 cpu 的執行並不是非常漂亮,有著許多的中斷並且都是片段在執行 writeFrameAsync 的操作,查了一下 Frame 是http2 的最小傳輸單元看起來應該是一直在傳送資料。

其實到這裡基本上已經大該可以猜測原因為壓測時候網路影響導致 upload file 的時間本身就拉得太長了。

由於我在進行壓測的時候是用我自己的 macbook m1 pro 由於這次的壓測有些因素所以換了壓測工具,並沒有先前建置好的一些環境。

為了貪圖方便我想說簡單的壓測,量也不是很大 m1 那麼強大應該用 mac 就可以了吧?

但我少算了現在大部分我都是以 remote 的方式工作,所以網路品質跟頻寬並不是那麼足夠。

為了近一步證實我的猜測便跟 chatGPT 確認 sync block與multipartForm的關係以及 gin multipartForm 實際運作方式。

由於先前也跟 chatGPT 確認在進行 multipart 發送 Request 的時候到底是只接收到一部分的資料就會進行 multipartForm 還是會等待資料全部接收完畢才會進行 multipartForm。

當時得到的回覆是要等到資料全部接收完畢才會進行 multipartForm,也就是因為這個回覆所以才有了上面的一堆事項QQ

最後把壓測拉到了 CI 上面去做在 multipartForm 的部分明顯改善了許多。

經過這次得經驗有了一些反省,自己對於 multipart 的相關經驗不足,導致在 debug 的時候不夠敏銳花的太多不必要的時間。

換個角度想也是這次這個機會才能夠真的運用上 pprof、fg prof、go trace 等工具。

結論

壓測的時候別偷懶該上公雲開機器就開機器,不行至少也要拉到 Github action 做

--

--