记一次获得3倍性能的Go程序优化实践

背景介绍

之前公司一直使用 Logstash 作为日志文件采集客户端程序。Logstash 功能强大，有丰富的数据处理插件及很好的扩展能力，但由于使用 JRuby 实现，性能堪忧。而 Filebeat 是后来出现的一个用 Go 语言实现的、更轻量级的日志文件采集客户端。性能不错、资源占用少，但几乎没有任何解析处理能力。

通常的使用场景是使用 Filebeat 采集到 Logstash 解析处理，然后再上传到 Kafka 或 Elasticsearch。值得注意的是，Logstash 和 Filebeat 都是 Elastic 公司的优秀开源产品。

为了提高客户端的日志采集性能，又减少数据传输环节和部署复杂度，并更充分地将 Go 语言的性能优势利用于日志解析，于是决定在 Filebeat 上通过开发插件的方式，实现针对公司日志格式规范的解析，直接作为 Logstash 的替代品。

实现与优化Version 1.0

先做一个最简单的实现，即用 Go 自带的正则表达式包 regexp 做日志解析。性能已经比 Logstash（也是通过开发插件做规范日志解析）高出 30%。

这里的性能测试着眼于日志采集的瓶颈——解析处理 环节，指标是在限制只使用一个 CPU core 的条件下（在服务器上要尽量减少对业务应用的资源占用），采集并解析 1 百万条指定格式和长度的日志所花费的时间。

测试环境是 1 台主频为 3.2GHz 的 PC。为了避免 disk IO 及 page cache 的影响，将输入文件和输出文件都放在 /dev/shm 中。对于 Filebeat 的 CPU 限制，是通过启动时指定环境变量 GOMAXPROCS=1 实现的。

这一版本处理 1 百万条日志花费的时间为 122 秒，即每秒 8200 条日志。

Version 2.0

接下来尝试做一些优化，看看这个 Go 插件的性能还可不可以有些提升。首先想到的是替换 regexp 包。Linux 下有一个 C 实现的 PCRE 库，https://github.com/glenn-brown/golang-pkg-pcre 这个第三方包正是将 PCRE 库应用到 Golang 中。CentOS 下需要先安装 pcre-devel 这个包。

这个版本的处理时间为 97 秒，结果显示比第一个版本的处理性能提升了 25%。

Version 3.0

第三个版本，是完全不使用正则表达式，而是针对固定的日志格式规则，利用 strings.Index() 做字符串分解和提取操作。这个版本的处理时间为 70 秒，性能又大大的提升了将近 40%。

Version 4.0

那还有没有进一步提升的空间呢？有。就是 Filebeat 用作序列化输出的 JSON 包。我们的日志上传使用 JSON 格式，而 Filebeat 使用 Go 自带的 encoding/json 包是基于反射实现的，性能一直广受诟病。如果对 JSON 解析有优化的话，性能提高会是很可观的。

既然我们的日志格式是固定的，解析出来的字段也是固定的，这时就可以基于固定的日志结构体做 JSON 的序列化，而不必用低效率的反射来实现。Go 有多个针对给定结构体做 JSON 序列化 / 反序列化的第三方包，我们这里使用的是 easyjson：https://github.com/mailru/easyjson。

在安装完 easyjson 包后，对定义了日志格式结构体的程序文件执行 easyjson 命令，会生成一个 xxx_easyjson.go 的文件，里面包含了这个结构体专用的 Marshal/Unmarshal 方法。

这样一来，处理时间又缩短为 61 秒，性能提高 15%。

这时，代码在我面前，已经想不出有什么大的方面还可以优化的了。是时候该本文的另一个主角，火焰图出场了。

on-cpu/off-cpu 火焰图

火焰图是性能分析的一个有效工具，http://www.brendangregg.com/flamegraphs.html 这里是它的说明。通常看到的火焰图，是指 on-cpu 火焰图，用来分析 CPU 都消耗在哪些函数调用上。

on-cpu 火焰图

安装完 FlameGraph：https://github.com/brendangregg/FlameGraph 工具后，先对目前版本的程序运行一次性能测试，按照说明抓取数据生成火焰图如下。

注：FlameGraph 对于 C/Go 程序是通用的。对于 Go 程序，也可以使用自带的 net/http/pprof 包作为数据源，然后安装 Uber 的 go-torch：https://github.com/uber/go-torch 工具来自动调用 FlameGraph 脚本生成 on-cpu 火焰图，执行会稍为简便一些。参见 go-torch 说明。

图中纵向代表的是函数调用栈，横向各个方块的宽度代表的是占用 CPU 时间的比例，需要留意的是靠近顶端的大长条。方块的颜色是随机的没有实际意义。

从上图可以看到 CPU 时间占用最多的主要有两块。一块是 Output 处理部分，稍为大头的是 JSON 处理，这块已经优化过没什么可以做的了。另一块就比较奇怪了，是 common.MapStr.Clone() 方法，居然占了 40% 的 CPU 时间。再往上看，主要是 Errorf 的处理。一看代码，马上明白了。

common.MapStr 是在 pipeline 中存放日志内容的结构体，它的 Clone() 方法实现里判断一个子键值是否为嵌套的 MapStr 结构时，是通过判断 toMapStr() 方法是否返回 error。从这里看，生成 error 对象的代价是非常可观的。于是，一个显然的 fix，就是将 toMapStr() 中的判断方法移到 Clone() 中并避免生成 error。

Version 5.0

对修改后的代码重新生成一张火焰图如下。

这时 common.MapStr.Clone() 从图中已经几乎找不见了，证明花费的 CPU 时间已经可以忽略不计。

测试时间一下子缩短到了 46 秒，节省了 33%，非常大的改善！

off-cpu 火焰图

到现在，还有一个之前未提到的问题没有解决——在限制使用一个 core 之后，测试运行时 CPU 利用率只能跑到 80% 多。是不是由于有锁存在影响了性能呢？

这时候，又该请 off-cpu 火焰图 出场了。off-cpu 火焰图，是用来分析程序没有有效利用 CPU 的时候，消耗在什么地方了，在 http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html 有详细的介绍。

数据收集比 on-cpu 火焰图要复杂，可以使用大名鼎鼎的春哥提供的 openresty-systemtap-toolkit：https://github.com/openresty/openresty-systemtap-toolkit 包。春哥的项目页面中没有详细说明的是 kernel-devel 和 debuginfo 包的安装方法。在此也记录一下。

安装完后按照说明生成了 off-cpu 火焰图如下：

可以明显地看到，对 Registry 文件（Filebeat 用于记录文件采集列表和 offset 数据）的写操作占了一定比例。于是，尝试将 Filebeat 的 spool_size（每完成这么多条日志更新一次 Registry 文件）设置为 10240，默认值的 5 倍，运行测试 CPU 已经可以跑到 95% 以上。而将 Registry 设置到 /dev/shm/ 下也同样可以解决测试时 CPU 跑不满的问题。

这就否定了上面对锁使用不当影响性能的猜测。在实际应用时 spool_size 的设置应当依据结合了 output 端（如写入到 Kafka）的测试数据来决定。

至此，优化结束，性能达到了最初版本的 3 倍！

各个版本的具体运行性能数据如下图所示：

需要稍作说明的是：

• Filebeat 开发是基于 5.3.1 版本，Go 版本是 1.8

• Logstash 的测试通过 -w 1 参数配置使用一个工作进程，并未限制使用一个 core

• 执行时间包括了程序的启动时间（Logstash 的启动时间有将近 20 秒）

最终的优化结果是，针对特定格式和长度的日志解析能力在 PC 上达到了每秒 25000 条，即使在 CPU 主频较低的生产服务器上，也可以达到每秒 20000 条。

Go 的高性能真不是吹的，当然是要在足够的优化后：）

最后，关于 Go 的性能有一篇这样的讨论，有兴趣可以看看：http://stackoverflow.com/questions/20875341/why-golang-is-slower-than-scala

原文来自:聊聊架构

声明：所有来源为“聚合数据”的内容信息，未经本网许可，不得转载！如对内容有异议或投诉，请与我们联系。邮箱：marketing@think-land.com