抽丝剥茧,记一次 Go 程序性能优化之旅

skyyoung
发布于 2023-6-21 11:55
浏览
0收藏

大家好,我是小楼。

在之前的文章​​《一言不合就重构》​​中介绍了我重构的一个服务健康检查系统,这个系统自上线开始就有一个问题:健康检查耗时有点高。但一直拖着没解决,究其原因只能拿出下面这张图。

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

背景介绍

在开始本文前,让大家快速进入状态,我们提取最简单的背景。

健康检查系统每隔一段时间会向目标服务器发送健康检查请求,当失败达到一定条件(例如连续3次失败),则将该目标从注册中心中摘除。

我们遇到一个问题:健康检查的耗时高。

虽然我们支持各种各样的健康检查请求,但这里主要还是 TCP 健康检查,也就是对目标服务发起 TCP 建连请求耗时比较高。多高呢?几毫秒到几十毫秒,甚至几百毫秒,平均下来40多毫秒。看着感觉还可以,但要知道 TCP 建连只需要三次握手,而且是内网,这样看来,确实离谱。

必要性

上面说了,慢就慢点,又不是不能用,为啥还要折腾呢?

这是因为有更多的服务要接入这个系统,比如原先是 Nginx 自带的主动健康检查也需要替换为这个系统。

但原先 Nginx 上配置的健康检查超时时间大多是 50 ~ 100ms,如果平迁到我这个系统,就可能出问题,由于检查耗时比较高,这些配置大概率会超时,导致服务被误摘。

如果把超时时间改大行不行呢?也不行,如果业务服务负载不均或单机有抖动导致耗时增高,原先的 Nginx 能发现并把不正常的节点摘除,但如果迁移到我的健康检查系统,就没法做到这点。

综上,还是很有必要查一下为什么建立一个 TCP 连接这么慢?

查监控

这次问题神奇之处是,监控上没有任何异常,包括 CPU、内存、磁盘、网络等一系列指标均无异常,甚至还表现的非常优秀,就只有健康检查耗时高。

找不同

首先,对比我们的程序和 Nginx 的主动健康检查,有什么区别,总结了几点:

  • Nginx 是 C 语言编写,我们的程序是 Go 编写;
  • Nginx 部署在物理机上,我们的程序部署在 Docker 上;
  • Nginx 上健康的服务量级比较少,我们的程序单机需要检查上万台目标服务;

做试验

基于这些不同点,我做了2个小实验:

  • 在物理机上部署这个健康检查系统,对一个服务进行健康检查,对比 Docker 容器上相同目标检查耗时发现,物理机耗时只有几毫秒;
  • 在另一个 Docker 上部署,也只对这个服务进行检查,发现耗时也只有几毫秒;

大胆猜测,检查耗时可能和检查的量级有关,并且我们的程序是有潜力达到和 Nginx 相当的水平的,大不了堆机器嘛。

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

怀疑协程调度

检查一个目标地址,需要开一个协程,量级大小就代表了 Go 协程数量级,于是猜测是不是 Go 协程调度导致耗时高?

所以怎么看 Go 协程调度花费了多少时间?查找资料,发现 Go Trace 工具可以看到调度耗时,前提是 Go 版本 >= 1.5,且开启 pprof,刚好我们都达到了。

采集数据:

curl -o trace.dump 'http://127.0.0.1:8600/debug/pprof/trace?seconds=30'

查看:

go tool trace trace.dump

具体介绍和简单使用可以参考这篇文章:​​《深入浅出 Go trace》​​。

比如我这里拿到了这样的结果:

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

采集了30s,单个协程在 30s 的运行中调度花费了300ms,感觉很多。

于是我又搜索,Go 协程调度什么情况下会慢,还真就让我找到了这篇文章:

《Go gomaxprocs 调高引起调度性能损耗》 https://cloud.tencent.com/developer/article/1848155

摘出重点:

在微服务体系下服务的部署通常是放在 docker 里的。一个宿主机里跑着大量的不同服务的容器。为了避免资源冲突,通常会合理地对每个容器做 cpu 资源控制。比如给一个 golang 服务的容器限定了 2 cpu core 的资源,容器内的服务不管怎么折腾,也确实只能用到大约 2 个 cpu core 的资源。

但 golang 初始化 processor 数量是依赖 /proc/cpuinfo 信息的,容器内的 cpuinfo 是跟宿主机一致的,这样导致容器只能用到 2 个 cpu core,但 golang 初始化了跟物理 cpu core 相同数量的 processor。

...

runtime processor 多了会出现什么问题?

一个是 runtime findrunnable 时产生的损耗,另一个是线程引起的上下文切换。

看到这里想到当年做 Java 上云时也遇到类似的问题,上云后 Java GC 线程数开了和物理机核数相同的数量,导致 GC 时上下文切换严重。

于是写个简单的 Go 程序,在容器上输出 GOMAXPROCS,发现果然是物理机的核数。怎么解决?我又查了一些资料,发现了这个库:

​https://github.com/uber-go/automaxprocs​

只要引入这个库,就能自动设置正确的 GOMAXPROCS,兼容各种环境。这就好办了,改好代码上线,一顿操作下来,发现耗时并没有肉眼可见的变化。

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

怀疑 GC

检查量级的不同必然带来内存分配和 GC 的压力,而且 Nginx 是 c 写的,手动释放内存,比高级语言自动 GC 要强很多,所以这里有必要怀疑一下。

这次还是用 trace 的看一下,专门挑了建立连接的 goroutine:

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

不看不知道,一看吓一跳,GC 暂停时间普遍占比很高,最高达到了100%,离谱!

于是点进去看看 GC 到底花在哪里?

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

随手点了几个,发现主要是2个点:

  • Debug 日志
  • Metric 上报

Debug 日志是用于定位线上问题的,直接关掉即可,有问题时再打开,由于这是我们自己实现的一个日志库,没有动态调整日志级别的能力,于是我给它加了一个动态调整日志级别的功能,平时关闭,需要时再打开。

关掉 Debug 日志平均耗时由40ms下降到了30ms。

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

再次 dump trace,发现耗时高的基本就是 metric 上报了,日志这部分 GC 不再出现,通过 heap dump 也能发现内存使用最多的是 metric 了,但这部分优化空间很小,因为这个库不是我们维护,只能去掉一些不必要的 metric,再就是扩容了。

原先我们是10台 8C16G 的 Docker,扩容到 20 台,发现平均耗时一下从 30ms 下降到 10ms:

抽丝剥茧,记一次 Go 程序性能优化之旅-鸿蒙开发者社区

虽然这样扩容能解决问题,但成本也不少,仔细观察内存使用情况,其实并没有使用多少内存,CPU 也是,资源其实还是极大地浪费了,于是我尝试把容器配置由 8C16G 换成 4C8G,结果发现效果一样,也就是说用相同的资源,耗时只有之前的 1/4。

GC 参数调整

到这里,我在想,Go 的 GC 能不能调整参数呢?于是我又查了一些资料,发现只有一个参数 GOGC 可以调整,这个参数代表了内存涨百分之多少进行一次 GC,例如200表示内存翻倍时进行一次 GC,越高则 GC 频率越低。于是我测试了100~1000,发现500时表现较好,平均耗时由10ms下降至8ms,效果有但没那么明显。

至于这里面的理论支撑依据,由于篇(我)幅(也)有(不)限(懂),可以在以后的文章中细说。

最后

优化到这里,基本能满足需求,没必要再优化,实在不行,还可以扩容。最终的成绩是在资源不变的情况下平均耗时由40ms下降到8ms,某个服务的耗时由120ms下降到10ms,效果非常明显。

整个过程其实不需要太多理论知识,只要善于使用工具,先猜测再实践论证,一层一层抽丝剥茧,终会搞定。


文章转载自公众号:捉虫大师

标签
已于2023-6-21 11:55:56修改
收藏
回复
举报
回复
    相关推荐