Golang日志扫描优化记录

本文主要记录一次日志扫描正则优化过程，项目中使用了火焰图性能分析、第三方正则库、tail包等，主要记录优化过程思路。

场景

首先讲一下应用场景，因为业务日志量比较大，每天产生的日志量大概在1000G左右。

现在需要实时的从这些日志中逐行扫描拿到日志信息并进行统计分析和报警，日志信息过滤这部分需要使用正则，因此对文件扫描过滤器的性能要求非常高。

用正则进行日志信息匹配，拿到一条目标日志，几乎每条日志信息都要配对多个正则表达式，所以扫描器日志读取速度和正则匹配的速度就成为了关键点。

下面是优化过程记录。

第一版

方案

最初的方案简单直接，对每一个需要监控的日志文件都开一个goroutine，goroutine里面使用tail包进行日志扫描，每次拿到一条日志直接使用正则进行数据匹配和过滤，然后转发至下游的ES。

测试

完成后进行联调测试发现速度特别慢，每秒只能读取200多行日志，实测一个有 191989 行数据的日志文件花费了819秒的时间，而且延迟严重，日志文件写入早已经完成，但是扫描过滤这边迟迟不能结束。

结果

初步认定是正则匹配比较慢的问题，因此开始修改方案，改造代码。

第二版

方案

预先开启固定数量的goroutine，这些goroutine都有一个自己独有的channel进行消息接收，然后将这些channel全部放入同一个channel队列中，也就是有一个传输chan类型的channel，相当于一个队列资源池，用的时候拿出一个channel传数据，用完再放回去，这是最开始初始化部分。

然后将所有的tail goroutine内的日志数据发送至一个百万量级channel进行缓冲，这个channel一旦接收到数据立即调起前面所说的资源池，将需要处理的日志信息传输给某个goroutine进行处理。

测试

测试后处理速度还是很慢，然后单独写了一个Demo测试tail包读取文件的速度，非常快，单独测试正则，也没有这么慢。

因此开始怀疑是不是其他地方导致的问题。

结果

认定不是正则的问题，但是当前依旧不清楚是哪里出现阻塞，需要拎出大招，使用火焰图查看耗时情况。

第三版

方案

使用火焰图查找性能瓶颈，首先是包含ES转发的CPU火焰图，发现第二张图中PushLog函数占用了大量的时间。


测试

将代码中的PushLog部分注释掉重新测试。


结果

对比之后发现，因为PushLog是直接放在正则匹配之后的，但是CPU消耗却是正则匹配的几十倍，而这个方法中有一个将接收日志的channel中的数据转发至ES的操作，查看错误日志发现，ES转发部分连接大量超时阻塞，导致正则匹配后的日志迟迟无法被消费，终于找到了问题所在。

第四版

方案

从上面的火焰图中可以看到，goroutine的调度（runtime.mcall）消耗了大量的CPU资源，如果不是正则的问题，那么使用goroutine处理正则并不能提升效率，因此继续修改代码方案，去掉goroutine队列池部分，直接使用正则处理日志缓冲通道收到的所有日志信息。

测试

后续的测试都会先剥离掉ES部分，此时相比于使用大量的goroutine处理正则的结构，性能略有提升，但是依旧不够，日志吞吐量还是上不去，这个时候正则处理部分成为了瓶颈。

结果

需要想办法提高正则的速度。

第五版

方案

面对正则比较慢的问题，一下没想到什么好的方案，遂去搜索，发现有人说，使用strings.Index进行关键字匹配会比较快，有一定的性能提升，于是尝试这种方案。

测试

经过测试，如果要匹配的关键字比较少，比如只有一两个，性能确实要比正则好一些，但是如果需要匹配很多的关键字，正则反而更好一些。

结果

需要寻找能够更好的处理正则的方案。

第六版

方案

预编译正则，go里面可以预先使用Compile方法预先解析编译正则表达式，所以加载配置文件后提前编译好，看看性能如何。

测试

结果

通过上面火焰图可以看出，效果不明显，并没有显著的变化，需要更好的方案。

第七版

方案

搜索知道golang自带的正则库性能比较差，通过网友博客找到一个第三方的正则库，rure-go库，这个库需要引入一个Rust编译的 .so 文件，然后使用rure库的正则API替代掉go语言regexp库的API。

关于rure-go的用法，文章最后会列出博客地址。

测试

原始正则

rure-go库正则


结果

通过上面的火焰图测试对比可以看到，新能大幅提升，从原来的接近30%的占比降低到只有3%左右，效果显著。

使用这个库唯一的麻烦之处是需要根据不同的平台编译不同的 .so 文件，然后执行的时候设置好环境变量，不过如果显著的性能提升，值得一用，因此修改代码结构为默认使用rure-go库，但是可以通过配置文件回退到go自身的regexp库。

第八版

方案

查看下图正则处理部分可以看到有一个 time.Time.Format 部分，占比和rure正则差不多，看代码发现数据转发部分有一个时间格式化为字符串，也就是 time.String()，字符串序列化从来都是资源消耗的大头，因此通过沟通后干掉了这个字段。

测试


结果

经过测试后能看到，正则处理部分性能进一步提升，主要资源消耗都聚集在了正则处理上，也就是上图的 IsMatch 方法。

完整测试对比

使用rure-go库


使用regexp库


regexp库会消耗更多的时间，占用更多的CPU资源，而rure-go库效果很好，配合tail与channel速度非常快，目前测试可以做到一秒内处理接近40000条日志信息，接近10w次的正则匹配。

结语

  • 不要滥用goroutine，会消耗大量的CPU性能，在程序运行过程中尽量不要频繁创建停止goroutine
  • 谨慎使用大量的正则匹配
  • 谨慎使用 String() 方法
  • 使用火焰图能够非常有效的找到程序性能瓶颈，关于火焰图的使用在后面参考链接中
  • go自带的regexp正则库性能较差，如果必须使用大量正则，使用rure-go库可以显著提升性能
  • 要有耐心，测试性能需要消耗大量的精力和时间，并且要反复测试给出测试结论

参考

下面链接是过程中参考的所有博文，贴在这里。

◀        
        ▶