背景:
容器化之前已经有一套es+flume+kibana日志收集系统,由于flume agent采集日志时候消耗的资源过大,容器平台采用更为轻量的filebeat来作为日志采集的客户端。为了兼容原有的efk,在filebeat的基础上开发了自定义output,用于把日志发至flume。
上线一段时间后,发现filebeat pod 疯狂吃内存,然后给pod配上的资源限制,发现有一台宿主机上的pod一直OOM。
filebeat工作流程
分成两个部分来说明filebeat的工作流程,采集、发送。
采集部分:
1、registrar.Run()协程负责更新记录日志的采集状态,
2、Crawler负责管理Input,根据配置文件创建Input
3、Input负责管理Harvester,定时扫描配置的paths路径,发现需要采集的日志文件,为每个日志文件都创建一个Harvester
4、Harvester 用来采集具体的日志文件,将日志发送到channel,所有Harvester的channel的日志都会被其所属Input读取,然后发送,同时日志采集信息也会同步到Registrar中。
发送部分:
1、所有output通过init把自己的构造函数注册到output reg中
2、createBeater时,会根据配置文件加载具体的output类型,并且把output注册到pipeline的consumer中,consumers的loop协程会循环读取采集到的日志文件,并通过output Publish方法发送。
排查问题:
1、dlv工具断点调试,除了帮我更了解代码运行流程之外,对问题排查并没有什么实际作用。
2、pprof+go-torch。之前用火焰图在分析cpu的时候感觉挺有用,所以这次用pprof时直接连同火焰图一起使用了。go tool pprof 对heap信息的采集跟profile不太一样,只有一次就直接生成了svg文件。这个图是把具体output发送的步骤的逻辑注释后生成的,因此看起来Harvester.Run()占的相对比较多,注释前更为平均,根本看不出来什么瓶颈。
3、pprof。由于问题很明显是内存泄漏,所以比较怀疑可能是协程泄漏,其中最有可能的就是Harvester.Run()协程泄漏。查看/debug/pprof/goroutine,发现goroutine700多个。有一定的数量,但是没有到泄漏到地步。在其他配置不变的情况下,把harvester_limits 设置成2,重新运行后Harvester协程数量大致等于input的两倍,总的协程数也降下来了。内存泄漏的问题还是存在。基本否定了是协程泄漏导致的内存泄漏。
4、还是pprof,直接go tool pprof http://host:port/debug/pprof/heap,top查看内存占用情况。发现占用几乎全是doAppend(),而且查看了doAppend()的逻辑后,也没发现什么问题。问题已经基本明确了,就是Harvester.Run()->Harventer.Reader.Next()->doAppend()引起的。由于自定义的output的Publish跟具体的发送数据之间是有缓冲的异步操作,怀疑可能是缓冲太长,导致Harvester.Next()瞬时调用过多或者发送太慢,缓冲满了后Harvester.Next()却没有被堵塞。查看代码调用逻辑,最终确定是由于Harventer采集日志时,必须要碰到"\n"才会把buffer里的内容返回,有些不符合规范的日志,一行大小就有10G。
2647.67MB 99.55% 99.55% 2647.67MB 99.55% [github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).doAppend](http://github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).doAppend)
4.06MB 0.15% 99.71% 2651.73MB 99.71% [github.com/elastic/beats/filebeat/reader/line.(*Reader).advance](http://github.com/elastic/beats/filebeat/reader/line.(*Reader).advance)
1.50MB 0.056% 99.76% 2653.74MB 99.78% [github.com/elastic/beats/filebeat/input/log.(*Harvester).Run](http://github.com/elastic/beats/filebeat/input/log.(*Harvester).Run)
0 0% 99.76% 2653.74MB 99.78% [github.com/elastic/beats/filebeat/harvester.(*Registry).Start.func1](http://github.com/elastic/beats/filebeat/harvester.(*Registry).Start.func1)
0 0% 99.76% 2651.73MB 99.71% [github.com/elastic/beats/filebeat/reader/encode.Reader.Next](http://github.com/elastic/beats/filebeat/reader/encode.Reader.Next)
0 0% 99.76% 2651.73MB 99.71% [github.com/elastic/beats/filebeat/reader/limit.(*Reader).Next](http://github.com/elastic/beats/filebeat/reader/limit.(*Reader).Next)
0 0% 99.76% 2651.73MB 99.71% [github.com/elastic/beats/filebeat/reader/line.(*Reader).Next](http://github.com/elastic/beats/filebeat/reader/line.(*Reader).Next)
0 0% 99.76% 2651.73MB 99.71% [github.com/elastic/beats/filebeat/reader/strip_newline.(*StripNewline).Next](http://github.com/elastic/beats/filebeat/reader/strip_newline.(*StripNewline).Next)
0 0% 99.76% 2647.67MB 99.55% [github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).Append](http://github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).Append)