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开发游戏的同学参考一下。

根据个人经验，建议尽量把请求时间保持在微秒级别，到了毫秒级别就要提高警惕想办法优化了，到了几十微秒应该就有很大的优化空间了。当然这些数据要根据项目类型和实时性要求来，如果是一个分布式系统，自身节点间通讯就要花掉几毫秒，如果请求处理时间要求在微秒级别就不实际了。