我们使用golang编写的线上服务,通常会设置一个golang runtime指标监控,包括goroutine num、gc num、gc pause 等等。最近的一次上线,发现 gc 相关的指标出现异常,gc num 和 gc pause 大幅升高。由于 golang 的 gc 是 stop the world 来做, gc 过多会抢占程序的正常执行时间,甚至影响对外提供的服务,因此暂停了上线,准备先把 gc 的问题修复下。
出问题时的 gc 监控如下:
其中蓝色曲线表示 gc num,黄色曲线表示 gc pause(单位ms),两个指标都是30s的累计数据。可以看到每30s的pause达到了秒级别。
登录到线上机器,通过 go tool pprof --alloc_objects http://localhost:xxxx/debug/pprof/heap
命令,查看对象分配的采样记录。发现比较大头的有reflect.Value
、encoding/json
、fmt.Sprint
。考虑到程序中为了更好地做抽象,使用了反射操作,而 reflect.Value
会将对象拷贝并分配到堆上,程序中的对象都是消息体,有的消息体会超大,因此会分配较多的堆内存。对程序做了一版优化,去掉这个反射逻辑,改为switch case
,重新上线,发现 gc 略有下降,但效果还是不够。
继续做 profile,已经没有了 reflect.Value
,于是只能再从另外两项入手。
这个程序是一个老程序的重构版,当时为了做diff测试,加了大量的日志,包括debug日志,甚至有些用来做diff的日志是marshal成json的。我们用的日志库没有做特殊处理,每条日志都会先调用 fmt.Sprint
,这个函数会把对象分配到堆上。针对上述情况,做了大量的日志删减,gc 略有下降但效果不够。
继续做性能分析,发现gc大头还是json相关操作。这个应用程序的主要功能就是处理json格式传入的消息,因此除非从 json 库着手改善,否则似乎解决不了问题。BTW,在处理的诸多消息中,有一类消息体占用字节数巨大,是其他消息的十倍以上。尝试取消订阅这类消息,发现gc立即好转,恢复到正常水平。不过,这条路径走不通。
分析本程序的特点,它基于消息触发的模式,每次消息到来就会处理,处理就会有堆对象产生。golang 的 gc 时机是根据当前与上次的 heap size 的比例来决定,默认情况下是100,即新增一倍就会触发。尝试把这个比例调大 export GOGC=400
,试图降低 gc 触发频率,发现效果还是不错的,两个指标均有明显下降,其他指标无明显异常,暂时先这样解决,以后有余力再做程序层面优化。