Go垃圾回收系列之十：實戰(zhàn)一例頻繁GC的性能問題
橫表示知識的寬度，豎是技術(shù)的深度，你可以自己選擇發(fā)展寬度還是深度的。假如是寬度，你懂很多皮毛的東西，但不深，那么這顆釘子打在墻上，隨便就可以拔下來被替換掉。但是假如你專業(yè)很深、技術(shù)上很扎實，就會越來越不可撼動。
弱小，就是我們最大的罪過。在本文中，筆者將實戰(zhàn)分析一個由于垃圾回收造成程序效率損失的例子。在排查內(nèi)存泄露的過程中，使用了trace工具（trace集成在了pprof http中,本文中不會介紹trace工具的使用方法）
在pprof的分析中，能夠知道一段時間內(nèi)的CPU占用、內(nèi)存分配、協(xié)程堆棧信息。這些信息都是一段時間內(nèi)數(shù)據(jù)的匯總，但是其并沒有提供整個周期內(nèi)發(fā)生的事件，例如指定的goroutines何時執(zhí)行，執(zhí)行了多長時間，什么時候陷入了堵塞，什么時候解除了堵塞，GC如何影響單個goroutine的執(zhí)行，STW中斷花費的時間是否太長等。這就是在Go1.5之后推出的trace工具的強大之處，其提供了指定時間內(nèi)程序發(fā)生的事件的完整信息，這些事件信息包括：
協(xié)程的創(chuàng)建、開始和結(jié)束；
協(xié)程的堵塞——系統(tǒng)調(diào)用、通道、鎖；
網(wǎng)絡(luò)I / O相關(guān)事件；
系統(tǒng)調(diào)用事件；
垃圾回收相關(guān)事件。
分析開始，查看程序在某段時間內(nèi)內(nèi)存的增長情況。
curl -o trace.out http://ip:6060/debug/pprof/trace?seconds=30
go tool trace trace.out通過查看trace可視化結(jié)果，發(fā)現(xiàn)GC在30秒的時間內(nèi)執(zhí)行了43次，每次GC時間大約在1ms，這種頻繁的垃圾回收會帶來一定的性能損失。同時，查看堆內(nèi)存的變化情況發(fā)現(xiàn)內(nèi)存呈現(xiàn)鋸齒狀，表明在垃圾回收時釋放了大量臨時垃圾內(nèi)存。
圖1 trace工具發(fā)現(xiàn)GC頻繁觸發(fā)
為了探究為什么發(fā)生了如此頻繁的垃圾回收，可以查看每一次GC發(fā)生時的堆棧信息，這仍然是依靠trace工具的強大功能。從概率的角度來講，當我們在堆棧信息中查看到多次在相同的函數(shù)處觸發(fā)了垃圾回收，那么該函數(shù)大概率是有問題的。如下所示，在堆棧信息中查看到saveFaceToRedis函數(shù)出現(xiàn)多次，其調(diào)用了makeslice函數(shù)分配內(nèi)存。可以通過顯示的函數(shù)所在的位置，在對應(yīng)的代碼中查看是否出現(xiàn)問題。
圖20-29 查看觸發(fā)GC的函數(shù)的堆棧信息
一般來講，這樣的問題是由于臨時分配的內(nèi)存過多，沒有合理復(fù)用內(nèi)存導(dǎo)致的。這種問題在短時間需要分配大量內(nèi)存的場景（例如為處理的圖片分配內(nèi)存、序列化與反序列化）比較常見。在本案例中，查看代碼發(fā)現(xiàn)，由于多次分配了過大的內(nèi)存導(dǎo)致垃圾回收頻繁發(fā)生。通過修改代碼，借助標準庫中sync.pool復(fù)用產(chǎn)生的內(nèi)存，輕松解決了出現(xiàn)的問題。再次通過trace工具查看程序的變化，發(fā)現(xiàn)30秒只執(zhí)行了2次GC。
圖20-30 修復(fù)問題后內(nèi)存與GC狀況恢復(fù)正常
推薦閱讀