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的相關信息。

用法類似這樣：

GODEBUG=gctrace=1 ./my_go_program 2>log_file

這是Linux的shell支持的語法，這樣設置環境變量只會作用於當前啟動的這個進程。

信息是輸出到標准錯誤的，所以需要用 2> 把輸出重定向到文件里。

輸出的內容像這樣：

垃圾回收信息

gc 1 @2.104s 0%: 0.018+1.3+0.076 ms clock, 0.054+0.35/1.0/3.0+0.23 ms cpu, 4->4->3 MB, 5 MB goal, 4 P。

1 表示第一次執行
@2.104s 表示程序執行的總時間
0% 垃圾回收時間占用的百分比，（不知道和誰比？難道是和上面的程序執行總時間，這樣比較感覺沒意義）
0.018+1.3+0.076 ms clock 垃圾回收的時間，分別為STW（stop-the-world）清掃的時間, 並發標記和掃描的時間，STW標記的時間
0.054+0.35/1.0/3.0+0.23 ms cpu 垃圾回收占用cpu時間
4->4->3 MB 堆的大小，gc后堆的大小，存活堆的大小
5 MB goal 整體堆的大小
4 P 使用的處理器數量

 

系統內存回收信息,這個很直白，看單詞就知道大概意思了
scvg0: inuse: 426, idle: 0, sys: 427, released: 0, consumed: 427 (MB)

426 使用多少M內存
0 剩下要清除的內存
427 系統映射的內存
0 釋放的系統內存
427 申請的系統內存

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

apiprof

apiprof不是Go自帶的功能，而是我在項目里自己做的，這個功能可以讓我在實時的觀測到程序的所有通訊接口的運行情況。

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

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

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

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