ELK 從發布5.0之后加入了beats套件之后，就改名叫做elastic stack了。beats是一組輕量級的軟件，給我們提供了簡便，快捷的方式來實時收集、豐富更多的數據用以支撐我們的分析。但由於beats都需要安裝在ELK集群之外，在宿主機之上，其對宿主機的性能的影響往往成為了考量其是否能被使用的關鍵，而不是它到底提供了什么樣的功能。因為業務的穩定運行才是核心KPI，而其他因運維而生的數據永遠是更低的優先級。影響宿主機性能的方面可能有很多，比如CPU占用率，網絡吞吐占用率，磁盤IO，內存等，這里我們詳細討論一下內存泄漏的問題
@[toc]
filebeat是beats套件的核心組件之一（另一個核心是metricbeat），用於采集文件內容並發送到收集端（ES），它一般安裝在宿主機上，即生成文件的機器。根據文檔的描述，filebeat是不建議用來采集NFS（網絡共享磁盤）上的數據的，因此，我們這里只討論filebeat對本地文件進行采集時的性能情況。
當filebeat部署和運行之后，必定會對cpu，內存，網絡等資源產生一定的消耗，當這種消耗能夠限定在一個可接受的范圍時，在企業內部的生產服務器上大規模部署filebeat是可行的。但如果出現一些非預期的情況，比如占用了大量的內存，那么運維團隊肯定是優先保障核心業務的資源，把filebeat進程給殺了。很可惜的是，內存泄漏的問題，從filebeat的誕生到現在就一直沒有完全解決過。（可以區社區討論貼看看，直到現在V6.5.1都還有人在報告內存泄漏的問題）。在特定的場景和配置下，內存占用過多已經成為了抑止filebeat大規模部署的主要問題了。在這里，我主要描述一下我碰到的在filebeat 6.0上遇到的問題。
問題場景和配置
一開始我們在很多機器上部署了filebeat，並且使用了一套統一無差別的的簡單配置。對於想要在企業內部大規模推廣filebeat的同學來說，這是大忌！！！ 合理的方式是具體問題具體分析，需對每台機器上產生文件的方式和rotate的方式進行充分的調研，針對不同的場景是做定制化的配置。以下是我們之前使用的配置：
multiline，多行的配置，當日志文件不符合規范，大量的匹配pattern的時候，會造成內存泄漏max_procs，限制filebeat的進程數量，其實是內核數，建議手動設為1
filebeat.prospectors:
- type: log
enabled: true
paths:
- /qhapp/*/*.log
tail_files: true
multiline.pattern: '^[[:space:]]+|^Caused by:|^.+Exception:|^\d+\serror'
multiline.negate: false
multiline.match: after
fields:
app_id: bi_lass
service: "{{ hostvars[inventory_hostname]['service'] }}"
ip_address: "{{ hostvars[inventory_hostname]['ansible_host'] }}"
topic: qh_app_raw_log
filebeat.config.modules:
path: ${path.config}/modules.d/*.yml
reload.enabled: false
setup.template.settings:
index.number_of_shards: 3
#index.codec: best_compression
#_source.enabled: false
output.kafka:
enabled: true
hosts: [{{kafka_url}}]
topic: '%{[fields][topic]}'
max_procs: 1
注意，以上的配置中，僅僅對cpu的內核數進行了限制，而沒有對內存的使用率進行特殊的限制。從配置層面來說，影響filebeat內存使用情況的指標主要有兩個：
queue.mem.events消息隊列的大小，默認值是4096，這個參數在6.0以前的版本是spool-size，通過命令行，在啟動時進行配置max_message_bytes單條消息的大小, 默認值是10M
filebeat最大的可能占用的內存是max_message_bytes * queue.mem.events = 40G，考慮到這個queue是用於存儲encode過的數據，raw數據也是要存儲的，所以，在沒有對內存進行限制的情況下，最大的內存占用情況是可以達到超過80G。
因此，建議是同時對filebeat的CPU和內存進行限制。
下面，我們看看，使用以上的配置在什么情況下會觀測到內存泄漏
監控文件過多
對於實時大量產生內容的文件，比如日志，常用的做法往往是將日志文件進行rotate，根據策略的不同，每隔一段時間或者達到固定大小之后，將日志rotate。 這樣，在文件目錄下可能會產生大量的日志文件。 如果我們使用通配符的方式，去監控該目錄，則filebeat會啟動大量的harvester實例去采集文件。但是，請記住，我這里不是說這樣一定會產生內存泄漏，只是在這里觀測到了內存泄漏而已，不是說這是造成內存泄漏的原因。
當filebeat運行了幾個月之后，占用了超過10個G的內存
非常頻繁的rotate日志
另一個可能是，filebeat只配置監控了一個文件，比如test2.log，但由於test2.log不停的rotate出新的文件，雖然沒有使用通配符采集該目錄下的所有文件，但因為linux系統是使用inode number來唯一標示文件的，rotate出來的新文件並沒有改變其inode number，因此，時間上filebeat還是同時開啟了對多個文件的監控。
另外，因為對文件進行rotate的時候，一般會限制rotate的個數，即到達一定數量時，新rotate一個文件，必然會刪除一個舊的文件，文件刪除之后，inode number是可以復用的，如果不巧，新rotate出來的文件被分配了一個之前已刪掉文件的inode number，而此時filebeat還沒有監測之前持有該inode number的文件已刪除，則會拋出以下異常：
2018-11-21T18:06:55+08:00 ERR Harvester could not be started on truncated file: /qhapp/logs/bd-etl/logs/test2.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: file info is not identical with opened file. Aborting harvesting and retrying file later again而類似Harvester setup failed.的異常會導致內存泄漏
https://github.com/elastic/beats/issues/6797
因為multiline導致內存占用過多
multiline.pattern: '^[[:space:]]+|^Caused by:|^.+Exception:|^\d+\serror，比如這個配置，認為空格或者制表符開頭的line是上一行的附加內容，需要作為多行模式，存儲到同一個event當中。當你監控的文件剛巧在文件的每一行帶有一個空格時，會錯誤的匹配多行，造成filebeat解析過后，單條event的行數達到了上千行，大小達到了10M，並且在這過程中使用的是正則表達式，每一條event的處理都會極大的消耗內存。因為大多數的filebeat output是需應答的，buffer這些event必然會大量的消耗內存。
模擬場景
這里不多說，簡單來一段python的代碼：
[loggers]
keys=root
[handlers]
keys=NormalHandler
[formatters]
keys=formatter
[logger_root]
level=DEBUG
handlers=NormalHandler
[handler_NormalHandler]
class=logging.handlers.TimedRotatingFileHandler
formatter=formatter
args=('./test2.log', 'S', 10, 200)
[formatter_formatter]
format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s以上，每隔10秒（'S', 'M' = 分鍾，'D'= 天）rotate一個文件，一共可以rotate 200個文件。 然后，隨便找一段日志，不停的打，以下是330條/秒
import logging
from logging.config import fileConfig
import os
import time
CURRENT_FOLDER = os.path.dirname(os.path.realpath(__file__))
fileConfig(CURRENT_FOLDER + '/logging.ini')
logger = logging.getLogger()
while True:
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!")
logger.debug("DEBUG 2018-11-26 09:31:35 com.sunyard.insurance.server.GetImage 43 - 資源請求:date=20181126&file_name=/imagedata/imv2/pool1/images/GXTB/2017/11/14/57/06b6bcdd31763b70b20f56c689e51f5e_1/06b6bcdd31763b70b20f56c689e51f5e_2.syd&file_encrypt=0&token=HUtGGG20GH4GAqq209R9tc9UGtAURR0b DEBUG 2018-11-26 09:31:40 com.sunyard.insurance.scheduler.job.DbEroorHandleJob 26 - [數據庫操作異常處理JOB]處理異常文件，本機不運行，退出任務!!@#!@#!@#!@#!@#!@#!@#!@#!@#!@#!@#!#@!!!@##########################################################################################################################################################")
time.sleep(0.03)如何觀察filebeat的內存
在6.3版本之前，我們是無法通過xpack的monitoring功能來觀察beats套件的性能的。因此，這里討論的是沒有monitoring時，我們如何去檢測filebeat的性能。當然，簡單的方法是通過top,ps等操作系統的命令進行查看，但這些都是實時的，無法做趨勢的觀察，並且都是進程級別的，無法看到filebeat內部的真是情況。因此，這里介紹如何通過filebeat的日志和pprof這個工具來觀察內存的使用情況
通過filebeat的日志
filebeat文件解讀
其實filebeat的日志，已經包含了很多參數用於實時觀測filebeat的資源使用情況，以下是filebeat的一個日志片段（這里的日志片段是6.0版本的，6.3版本之后，整個日志格式變了，從kv格式變成了json對象格式，xpack可以直接通過日志進行filebeat的monitoring）：
2018-11-02T17:40:01+08:00 INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=623475680 beat.memstats.memory_alloc=391032232 beat.memstats.memory_total=155885103371024 filebeat.events.active=-402 filebeat.events.added=13279 filebeat.events.done=13681 filebeat.harvester.closed=1 filebeat.harvester.open_files=7 filebeat.harvester.running=7 filebeat.harvester.started=2 libbeat.config.module.running=0 libbeat.output.events.acked=13677 libbeat.output.events.batches=28 libbeat.output.events.total=13677 libbeat.outputs.kafka.bytes_read=12112 libbeat.outputs.kafka.bytes_write=1043381 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 libbeat.pipeline.events.filtered=4 libbeat.pipeline.events.published=13275 libbeat.pipeline.events.total=13279 libbeat.pipeline.queue.acked=13677 registrar.states.cleanup=1 registrar.states.current=8 registrar.states.update=13681 registrar.writes=28
里面的參數主要分成三個部分：
beat.*，包含memstats.gc_next，memstats.memory_alloc，memstats.memory_total，這個是所有beat組件都有的指標，是filebeat繼承來的，主要是內存相關的，我們這里特別關注memstats.memory_alloc，alloc的越多，占用內存越大filebeat.*，這部分是filebeat特有的指標，通過event相關的指標，我們知道吞吐，通過harvester，我們知道正在監控多少個文件，未消費event堆積的越多，havester創建的越多，消耗內存越大libbeat.*，也是beats組件通用的指標，包含outputs和pipeline等信息。這里要主要當outputs發生阻塞的時候，會直接影響queue里面event的消費，造成內存堆積registrar，filebeat將監控文件的狀態放在registry文件里面，當監控文件非常多的時候，比如10萬個，而且沒有合理的設置close_inactive參數，這個文件能達到100M，載入內存后，直接占用內存
filebeat日志解析
當然，我們不可能直接去讀這個日志，既然我們使用ELK，肯定是用ELK進行解讀。因為是kv格式，很方便，用logstash的kv plugin：
filter {
kv {}
}kv無法指定properties的type，所以，我們需要稍微指定了一下索引的模版：
PUT _template/template_1
{
"index_patterns": ["filebeat*"],
"settings": {
"number_of_shards": 1
},
"mappings": {
"doc": {
"_source": {
"enabled": false
},
"dynamic_templates": [
{
"longs_as_strings": {
"match_mapping_type": "string",
"path_match": "*beat.*",
"path_unmatch": "*.*name",
"mapping": {
"type": "long"
}
}
}
]
}
}
}上面的模版，將kv解析出的properties都mapping到long類型，但注意"path_match": "*beat.*"無法match到registrar的指標，讀者可以自己寫一個更完善的mapping。 這樣，我們就可以通過kibana可視化組件，清楚的看到內存泄漏的過程
以及資源的使用情況：
將信息可視化之后，我們可以明顯的發現，內存的突變和ERR是同時發生的
即以下error： 2018-11-27T09:05:44+08:00 ERR Harvester could not be started on new file: /qhapp/logs/bd-etl/logs/test2.log, Err: Error setting up harvester: Harvester setup failed. Unexpected file opening error: file info is not identical with opened file. Aborting harvesting and retrying file later again
會導致filebeat突然申請了額外的內存。具體請查看issue
通過pprof
眾所周知，filebeat是用go語言實現的，而go語言本身的基礎庫里面就包含pprof這個功能極其強大的性能分析工具，只是這個工具是用於debug的，在正常模式下，filebeat是不會啟動這個選賢的，並且很遺憾，在官方文檔里面根本沒有提及我們可以使用pprof來觀測filebeat。我們接下來可以通過6.3上修復的一個內存泄漏的issue，來學習怎么使用pprof進行分析
啟動pprof監測
首先，需要讓filebeat在啟動的時候運行pprof，具體的做法是在啟動是加上參數-httpprof localhost:6060，即/usr/share/filebeat/bin/filebeat -c /etc/filebeat/filebeat.yml -path.home /usr/share/filebeat -path.config /etc/filebeat -path.data /var/lib/filebeat -path.logs /var/log/filebeat -httpprof localhost:6060。這里只綁定了localhost，無法通過遠程訪問，如果想遠程訪問，應該使用0.0.0.0。 這時，你就可以通過curl http://localhost:6060/debug/pprof/heap > profile.txt等命令，獲取filebeat的實時堆棧信息了。
遠程連接
當然，你也可以通過在你的本地電腦上安裝go，然后通過go tool遠程連接pprof。 因為我們是需要研究內存的問題，所以以下連接訪問的是/heap子路徑 go tool pprof http://10.60.x.x:6060/debug/pprof/heap
top 命令
連接之后，你可以通過top命令，查看消耗內存最多的幾個實例：
33159.58kB of 33159.58kB total ( 100%)
Dropped 308 nodes (cum <= 165.80kB)
Showing top 10 nodes out of 51 (cum >= 512.04kB)
flat flat% sum% cum cum%
19975.92kB 60.24% 60.24% 19975.92kB 60.24% runtime.malg
7680.66kB 23.16% 83.40% 7680.66kB 23.16% github.com/elastic/beats/filebeat/channel.SubOutlet
2048.19kB 6.18% 89.58% 2048.19kB 6.18% github.com/elastic/beats/filebeat/prospector/log.NewHarvester
1357.91kB 4.10% 93.68% 1357.91kB 4.10% runtime.allgadd
1024.08kB 3.09% 96.76% 1024.08kB 3.09% runtime.acquireSudog
544.67kB 1.64% 98.41% 544.67kB 1.64% github.com/elastic/beats/libbeat/publisher/queue/memqueue.NewBroker
528.17kB 1.59% 100% 528.17kB 1.59% regexp.(*bitState).reset
0 0% 100% 528.17kB 1.59% github.com/elastic/beats/filebeat/beater.(*Filebeat).Run
0 0% 100% 512.04kB 1.54% github.com/elastic/beats/filebeat/channel.CloseOnSignal.func1
0 0% 100% 512.04kB 1.54% github.com/elastic/beats/filebeat/channel.SubOutlet.func1查看堆棧調用圖
輸入web命令，會生產堆棧調用關系的svg圖，在這個svg圖中，你可以結合top命令一起查看，在top中，我們已經知道github.com/elastic/beats/filebeat/channel.SubOutlet占用了很多的內存，在圖中，展現的是調用關系棧，你可以看到這個類是怎么被實例化的，並且在整個堆中，內存是怎么分布的。最直觀的是，實例所處的長方形面積越大，代表占用的內存越多。：
查看源碼
通過list命令，可以迅速查看可以實例的問題源碼，比如在之前的top10命令中，我們已經看到github.com/elastic/beats/filebeat/channel.SubOutlet這個類的實例占用了大量的內存，我們可以通過list做進一步的分析，看看這個類內部在哪個語句開始出現內存的占用：
(pprof) list SubOutlet
Total: 32.38MB
ROUTINE ======================== github.com/elastic/beats/filebeat/channel.SubOutlet in /home/jeremy/src/go/src/github.com/elastic/beats/filebeat/channel/util.go
7.50MB 7.50MB (flat, cum) 23.16% of Total
. . 15:// SubOutlet create a sub-outlet, which can be closed individually, without closing the
. . 16:// underlying outlet.
. . 17:func SubOutlet(out Outleter) Outleter {
. . 18: s := &subOutlet{
. . 19: isOpen: atomic.MakeBool(true),
1MB 1MB 20: done: make(chan struct{}),
2MB 2MB 21: ch: make(chan *util.Data),
4.50MB 4.50MB 22: res: make(chan bool, 1),
. . 23: }
. . 24:
. . 25: go func() {
. . 26: for event := range s.ch {
. . 27: s.res <- out.OnEvent(event) 如何調優
其實調優的過程就是調整參數的過程，之前說過了，和內存相關的參數, max_message_bytes,queue.mem.events,queue.mem.flush.min_events，以及隊列占用內存的公式:max_message_bytes * queue.mem.events
output.kafka:
enabled: true
# max_message_bytes: 1000000
hosts: ["10.60.x.x:9092"]
topic: '%{[fields][topic]}'
max_procs: 1
#queue.mem.events: 256
#queue.mem.flush.min_events: 128但其實，不同的環境下，不同的原因都可能會造成filebeat占用的內存過大，此時，需要仔細的確認你的上下文環境：
- 是否因為通配符的原因，造成同時監控數量巨大的文件，這種情況應該避免用通配符監控無用的文件。
- 是否文件的單行內容巨大，確定是否需要改造文件內容，或者將其過濾
- 是否過多的匹配了multiline的pattern，並且多行的event是否單條體積過大。這時，就需要暫時關閉multiline，修改文件內容或者multiline的pattern。
- 是否output經常阻塞，event queue里面總是一直緩存event。這時要檢查你的網絡環境或者消息隊列等中間件是否正常
本文地址：http://elasticsearch.cn/article/6206