Go語言程式的狀態監控

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

Go是很實在的程式設計語言，從一開始就提供了很詳細的運行狀態資訊。產品上線後的調優和排查疑難雜症都得靠這些狀態資訊。這邊總結一些我們項目裡用到的狀態監控手段。

pprof

Go內建了一個pprof工具，這個工具可以做CPU和記憶體的profiling，官方的部落格有一篇文章介紹用法：《Profiling Go Programs》

官方的文章講了怎麼用內建的pprof工具分析資料，但是獲得分析資料的部分比較單一，我在很長一段時間一直誤以為cpuprof和memprof必須在程式啟動時開啟，其實cpuprof和memprof是可以線上開啟和關閉的。

並且pprof模組其實不只是cpuprof和memprof這兩個功能，其中還提供了Lookup功能用於擷取堆狀態資訊、線程狀態資訊、 goroutine狀態資訊等。

以下是我在項目中用到的pprof功能（程式碼片段）：

        case "lookup heap":            p := pprof.Lookup("heap")            p.WriteTo(os.Stdout, 2)        case "lookup threadcreate":            p := pprof.Lookup("threadcreate")            p.WriteTo(os.Stdout, 2)        case "lookup block":            p := pprof.Lookup("block")            p.WriteTo(os.Stdout, 2)        case "start cpuprof":            if cpuProfile == nil {                if f, err := os.Create("game_server.cpuprof"); err != nil {                    log.Printf("start cpu profile failed: %v", err)                } else {                    log.Print("start cpu profile")                    pprof.StartCPUProfile(f)                    cpuProfile = f                }            }        case "stop cpuprof":            if cpuProfile != nil {                pprof.StopCPUProfile()                cpuProfile.Close()                cpuProfile = nil                log.Print("stop cpu profile")            }        case "get memprof":            if f, err := os.Create("game_server.memprof"); err != nil {                log.Printf("record memory profile failed: %v", err)            } else {                runtime.GC()                pprof.WriteHeapProfile(f)                f.Close()                log.Print("record memory profile")            }

其中"lookup goroutine"和"lookup heap"都曾經幫我實際的解決過問題。有一次內網測試伺服器因為一個功能邏輯陷入死結，通過"lookup goroutine"擷取到當前所有正在啟動並執行goroutine的調用棧資訊，可以快速的排查出是哪些goroutine的調用發生了死結。

通過"lookup heap"可以看出堆的分存分配情況，可以快速的定位到記憶體流失的地方。"lookup heap"還提供了對象數量和每次GC執行的暫停時間，這些資訊對Go程式的GC調優很有用。

"start cpuprof"和"start memprof"可以線上的動態啟用cpuprof和memprof，這裡有個細節需要注意，我的程式一開始是自己實現daemon模式來做後台運行，剛加上"start cpurprof"的時候，線上動態啟用cpuprof會讓進程停止回應，不用daemon模式啟動就不會，最後我沒辦法只好去掉自己實現的daemon模式啟動，改為nohup讓程式在後台運行。

如果有自己實現daemon模式啟動並執行通訊，請留意。

cpuprof和memprof有還有一個細節需要注意，做cpuprof的程式需要給最後交給pprof做分析的程式是一致的，至少編譯時間候使用的代碼和代碼路徑需要是一致的，這跟程式裡帶的調試資訊有關係，否則產生出來的profile報表是不準的。

GOGCTRACE

Go提供了一些很有用的環境變數，可以讓程式在不修改代碼的情況下，做一些運行時的設定調整，比如GOMAXPROC，即可以通過環境變數設定，也可以通過代碼設定，我傾向於用環境變數設定，更為靈活。

其中GOGCTRACE環境變數在我做GC調優的時候起了很關鍵的作用，將GOGCTRACE設定為1，Go程式就會在每次GC的時候輸出GC的相關資訊。

用法類似這樣：

GOGCTRACE=1 ./my_go_program 2>log_file

這是Linux的shell支援的文法，這樣設定環境變數只會作用於當前啟動的這個進程。

資訊是輸出到標準錯誤的，所以需要用 2> 把輸出重新導向到檔案裡。

輸出的內容像這樣：

gc16(8): 34+6+5 ms, 367 -> 365 MB 817253 -> 782045 (18216892-17434847) objects, 64(2182) handoff, 72(22022) steal, 553/244/51 yields

其中gc16表示第16次進行GC，後面的(8)表示由8個線程執行，這個線程數對應GOMAXPROCS環境變數，34+6+5 ms分別代表一系列GC動作消耗的時間，這三個時間加起來45ms，就是這個程式在這次GC過程中暫停時間。

apiprof

apiprof不是Go內建的功能，而是我在項目裡自己做的，這個功能可以讓我在即時的觀測到程式的所有通訊介面的運行情況。

apiprof監控的是所有通訊介面的執行時間，每次請求處理完，就給apiprof進程發送一個資訊，其中包含請求的類型以及請求的執行時間。

apiprof進程匯總所有請求發來的資料，做進一步統計，比如某種請求的平均執行時間、最長執行時間等，然後輸出成一份表格，按請求執行時間排序，這樣就很容易抓到程式的效能瓶頸。

目前我們遊戲的總體請求執行時間在30微秒左右，其中從單個請求類型看，比較高耗時的請求執行時間是200微秒左右，其餘的大多在幾十微秒。這些資料可以給正在用Go開發遊戲的同學參考一下。

根據個人經驗，建議盡量把請求時間保持在微秒層級，到了毫秒層級就要提高警惕想辦法最佳化了，到了幾十微秒應該就有很大的最佳化空間了。當然這些資料要根據項目類型和即時性要求來，如果是一個分布式系統，自身節點間通訊就要花掉幾毫秒，如果請求處理時間要求在微秒層級就不實際了。