10年前,谷歌遇到一个由C++编译时间过长造成的严重瓶颈,他们需要全新的解决方案。为应对这一挑战,谷歌工程师创建了一种叫Go(又名Golang)的新编程语言。Go语言借鉴了C++的优点(比如其性能和安全特性),同时结合了Python的开发速度,这让其能快速使用多个核心,实现并发计算。
在Coralogix,我们解析客户日志来为它们提供相应的实时分析、警报和元数据等。为做到这一点,解析阶段必须非常快,但解析阶段却又非常复杂,并需要为每一个日志行服务加载大量规则。这是我们觉得采用Golang的原因之一。
这项新服务全天候运行在我们的生产环境中。虽然结果很不错,但是它仍然需要运行在高性能的机器上。这个Go服务运行在一台8核CPU和36GB内存的AWS m4.2xlarge实例上,每天解析超过数百亿的日志。
这个阶段,一切运行正常,可以将就,但这不是我们的风格,我们希望用更少的AWS实例来提供更多的功能,比如性能等。为实现这一目标,我们需要了解瓶颈的本质,以及如何能减少或完全消除它们。
我们决定在服务上运行一些性能分析,并检查是什么导致CPU的高消耗,看看是否可以做些优化工作。
首先,我们将GO升级到最新的稳定版本(软件生命周期中的关键一步)。此前,我们的版本是1.12.4,现在用的是1.13.8。
根据官方文档,1.13版本在runtime library和一些对内存使用有很大影响的组件进行了重大改进。不管怎么说,使用最新的稳定版本很有意义,并且为我们节省了很多工作。
因此,内存消耗也从800MB左右优化到180MB左右。
其次,为更好地理解我们的工作流程,并了解我们在哪里花费时间和资源,我们开始进行分析。
分析不同的服务和编程语言可能看起来非常复杂并令人生畏,但是在Go中,它实际上非常简单,仅用几个命令就可以实现。Go有一个叫"pprof"的专门工具,可以通过监听路由(默认端口为6060)在应用程序中启用该工具,并使用Go包来管理HTTP连接:
import _ "net/http/pprof"
然后,在主函数或者路由包中启用如下操作:
go func() {
log.Println(http.ListenAndServe("localhost:6060",nil))
}()
现在我们可以启动服务并连接到
Http://localhost:6060/debug/pprof
完整的Go文档可以参阅此处。
pprof的默认配置是每隔30秒对CPU使用率进行采样。我们可以调整一些配置从而实现对CPU使用率、heap usage等参数的采样。我们主要关注的是CPU的使用情况,因此在生产阶段中,我们采取一个30秒间隔的性能采样,并发现下图中的显示内容(注意:这是在我们升级了Go版本并将Go的内部组件降到最低之后的结果):
Go profiling
如你所见,我们发现很多与运行时库(runtime package )相关的活动,其中需要特别指出是GC(垃圾收集):几乎29%的CPU被GC使用,这还只是消耗最多的前20个对象。由于Go的GC已经非常快并做了很大优化,最好的实践就是不要去改变或修改它。由于我们的内存消耗非常低(与前一个Go版本相比),所以主要问题变成了高对象分配率。
如果是这样的话,我们可以做两件事情:
观察一下实例类型,我们有大量的空闲内存,而CPU数量则被机器类型所限制。因此我们需要调整这个比率。从Golang早期开始,就有一个阀值(flag)被大多数开发人员所忽视:GOGC。该阀值的缺省值为100,它的主要工作就是告诉系统何时触发GC。当堆达到其初始大小的100%时,默认值将触发GC进程。将默认值更改为更高数字则延迟GC触发,反之,将更快地触发GC。我们开始针对不同的数值进行基准测试,最终发现当GOGC=2000时,我们能获得最佳性能。
这将我们的内存使用量从200 MB立刻增加到2.7 GB(这还是在我们更新Go版本减少了内存消耗之后),并将我们的CPU使用率降低10%。
下面的截图展示了这些基准测试的结果:
Gogc=2000的结果
CPU使用率排名前4的函数变成了我们的服务函数,这才说得过去。现在,总的GC使用量变成了约13%,比之前的一半还少。
我们本可以就此打住,但我们还是决定继续去调查分配这么多对象的位置以及原因。很多时候,分配对象都有一个很好的理由(例如在流处理的情况下,我们为每条消息都创建了很多新对象,因为它与下一条消息无关,需要移除它),但在某些情况下,有一种简单的方法可以优化并极大地减少对象创建。
首先,让我们运行一个和之前相同的命令,只做一个小小的变动,采用heap dump:
Http://localhost:6060/debug/pprof/heap
为了查询结果文件,我们可以在代码文件目录中运行如下命令来分析调试结果:
go tool pprof -allocobjects <HEAP.PROFILE.FILE>
我们的截图看起来是这样的:
除第三行外,一切似乎都很合理。第三行是一个监控函数,在每个Coralogix规则解析阶段的末尾向我们的Promethes导出者(exporter)输出报告。为获取进一步的信息,我们运行以下命令:
list <FunctionName>
例如:
list reportRuleExecution
然后,我们得到以下结果:
这两个对WithLabelValues的调用其实是针对度量的Prometheus调用(我们让产品来决定是否真的需要它)。此外,我们看到第一行创建了大量对象(占该函数总分配对象的10%)。通过进一步研究,我们发现这是一个将客户ID从int转换为string的过程。该过程非常重要,但考虑到数据库中的客户数量有限,我们不应该为迎合Prometheus而将变量作为字符串接收。因此,我们没有在每次创建一个新字符串并在函数结束时丢弃它(浪费了分配时间和GC的更多工作),而是在对象初始化时定义了一个映射,映射了从1到10万之间的所有数字以及一个相对应的”get”操作。
我们运行了一个新的性能分析会话来验证上述论点,结果证明它是正确的(我们可以看到这部分不再分配对象了):
这并不是一个非常大的改动,但总的来说,这为我们节省了另一个GC活动,更具体地说,大约1%的CPU使用率。
最终状态显示在下面的截图中:
内存使用:~1.3GB -> ~2.7GB
CPU 使用:~2.55均值和~5.05峰值 -> ~2.13均值和~2.9峰值。
Golang优化之前的CPU使用率:
Golang优化之后的CPU使用率:
总的来说,我们的改进主要体现在峰值时间段,每秒处理的日志数量提升了。这意味着我们的基础设施不再需要针对异常值进行调优,而且变得更加稳定。
通过分析Go解析服务,我们能定位出问题区域,更好地理解我们的服务,并决定在哪里(如果有的话)投入时间来做改进工作。大多数性能分析工作最终都会参照用户使用情况对阀值或配置进行调优,从而获得更好的性能。
英文原文:
领取专属 10元无门槛券
私享最新 技术干货