记一次golang gc优化过程

zippera · · 7594 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

我们使用golang编写的线上服务,通常会设置一个golang runtime指标监控,包括goroutine num、gc num、gc pause 等等。最近的一次上线,发现 gc 相关的指标出现异常,gc num 和 gc pause 大幅升高。由于 golang 的 gc 是 stop the world 来做, gc 过多会抢占程序的正常执行时间,甚至影响对外提供的服务,因此暂停了上线,准备先把 gc 的问题修复下。

出问题时的 gc 监控如下:


image.png
image.png

其中蓝色曲线表示 gc num,黄色曲线表示 gc pause(单位ms),两个指标都是30s的累计数据。可以看到每30s的pause达到了秒级别。

登录到线上机器,通过 go tool pprof --alloc_objects http://localhost:xxxx/debug/pprof/heap 命令,查看对象分配的采样记录。发现比较大头的有reflect.Valueencoding/jsonfmt.Sprint。考虑到程序中为了更好地做抽象,使用了反射操作,而 reflect.Value 会将对象拷贝并分配到堆上,程序中的对象都是消息体,有的消息体会超大,因此会分配较多的堆内存。对程序做了一版优化,去掉这个反射逻辑,改为switch case,重新上线,发现 gc 略有下降,但效果还是不够。

image.png
image.png

继续做 profile,已经没有了 reflect.Value,于是只能再从另外两项入手。

这个程序是一个老程序的重构版,当时为了做diff测试,加了大量的日志,包括debug日志,甚至有些用来做diff的日志是marshal成json的。我们用的日志库没有做特殊处理,每条日志都会先调用 fmt.Sprint,这个函数会把对象分配到堆上。针对上述情况,做了大量的日志删减,gc 略有下降但效果不够。

image.png
image.png

继续做性能分析,发现gc大头还是json相关操作。这个应用程序的主要功能就是处理json格式传入的消息,因此除非从 json 库着手改善,否则似乎解决不了问题。BTW,在处理的诸多消息中,有一类消息体占用字节数巨大,是其他消息的十倍以上。尝试取消订阅这类消息,发现gc立即好转,恢复到正常水平。不过,这条路径走不通。

分析本程序的特点,它基于消息触发的模式,每次消息到来就会处理,处理就会有堆对象产生。golang 的 gc 时机是根据当前与上次的 heap size 的比例来决定,默认情况下是100,即新增一倍就会触发。尝试把这个比例调大 export GOGC=400,试图降低 gc 触发频率,发现效果还是不错的,两个指标均有明显下降,其他指标无明显异常,暂时先这样解决,以后有余力再做程序层面优化。

image.png
image.png

有疑问加站长微信联系(非本文作者)

本文来自:简书

感谢作者:zippera

查看原文:记一次golang gc优化过程

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:1006366459

7594 次点击  
加入收藏 微博
3 回复  |  直到 2017-09-26 01:45:41
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传