我们使用golang编写的线上服务，通常会设置一个golang runtime指标监控，包括goroutine num、gc num、gc pause 等等。最近的一次上线，发现 gc 相关的指标出现异常，gc num 和 gc pause 大幅升高。由于 golang 的 gc 是 stop the world 来做， gc 过多会抢占程序的正常执行时间，甚至影响对外提供的服务，因此暂停了上线，准备先把 gc 的问题修复下。
出问题时的 gc 监控如下：
image.png
其中蓝色曲线表示 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 略有下降，但效果还是不够。
image.png
�继续做 profile，已经没有了 reflect.Value，于是只能再从另外两项入手。
这个程序是一个老程序的重构版，当时为了做diff测试，加了大量的日志，包括debug日志，甚至有些用来做diff的日志是marshal成json的。我们用的日志库没有做特殊处理，每条日志都会先调用 fmt.Sprint，这个函数会把对象分配到堆上。针对上述情况，做了大量的日志删减，gc 略有下降但效果不够。
image.png
继续做性能分析，发现gc大头还是json相关操作。这个应用程序的主要功能就是处理json格式传入的消息，因此除非从 json 库着手改善，否则似乎解决不了问题。BTW，在处理的诸多消息中，有一类消息体占用字节数巨大，是其他消息的十倍以上。尝试取消订阅这类消息，发现gc立即好转，恢复到正常水平。不过，这条路径走不通。
分析本程序的特点，它基于消息触发的模式，每次消息到来就会处理，处理就会有堆对象产生。golang 的 gc 时机是根据当前与上次的 heap size 的比例来决定，默认情况下是100，即新增一倍就会触发。尝试把这个比例调大 export GOGC=400，试图降低 gc 触发频率，发现效果还是不错的，两个指标均有明显下降，其他指标无明显异常，暂时先这样解决，以后有余力再做程序层面优化。
image.png
网友评论