Go是很实在的编程语言,从一开始就提供了很详细的运行状态信息。产品上线后的调优和排查疑难杂症都得靠这些状态信息。这边总结一些我们项目里用到的状态监控手段。
pprof
Go自带了一个pprof工具,这个工具可以做cpu和内存的profiling,官方的博客有一篇文章介绍用法:《Profiling Go Programs》
官方的文章讲了怎么用自带的pprof工具分析数据,但是获得分析数据的部分比较单一,我在很长一段时间一直误以为cpuprof和memprof必须在程序启动时打开,其实cpuprof和memprof是可以在线打开和关闭的。
并且pprof模块其实不只是cpuprof和memprof这两个功能,其中还提供了Lookup功能用于获取堆状态信息、线程状态信息、 goroutine状态信息等。
case "lookup heap": p := pprof.Lookup("heap") p.WriteTo(os.Stdout, 2) "lookup threadcreate": p := pprof.Lookup("threadcreate") p.WriteTo(os.Stdout,116)">"lookup block": p := pprof.Lookup("block") p.WriteTo(os.Stdout,116)">"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 } } "stop cpuprof": if cpuProfile != nil { pprof.StopcpuProfile() cpuProfile.Close() cpuProfile = nil log.Print("stop cpu profile") } "get memprof": "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+65 ms, 367 -> 365 MB 817253 782045 (18216892-17434847) objects64(2182) handoff72(22022) steal553/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开发游戏的同学参考一下。
根据个人经验,建议尽量把请求时间保持在微秒级别,到了毫秒级别就要提高警惕想办法优化了,到了几十微秒应该就有很大的优化空间了。当然这些数据要根据项目类型和实时性要求来,如果是一个分布式系统,自身节点间通讯就要花掉几毫秒,如果请求处理时间要求在微秒级别就不实际了。