ELK 從發佈5.0以後加入了beats套件以後,就更名叫作elastic stack了。beats是一組輕量級的軟件,給咱們提供了簡便,快捷的方式來實時收集、豐富更多的數據用以支撐咱們的分析。但因爲beats都須要安裝在ELK集羣以外,在宿主機之上,其對宿主機的性能的影響每每成爲了考量其是否能被使用的關鍵,而不是它到底提供了什麼樣的功能。由於業務的穩定運行纔是核心KPI,而其餘因運維而生的數據永遠是更低的優先級。影響宿主機性能的方面可能有不少,好比CPU佔用率,網絡吞吐佔用率,磁盤IO,內存等,這裏咱們詳細討論一下內存泄漏的問題node
@[toc]python
filebeat是beats套件的核心組件之一(另外一個核心是metricbeat),用於採集文件內容併發送到收集端(ES),它通常安裝在宿主機上,即生成文件的機器。根據文檔的描述,filebeat是不建議用來採集NFS(網絡共享磁盤)上的數據的,所以,咱們這裏只討論filebeat對本地文件進行採集時的性能狀況。linux
當filebeat部署和運行以後,一定會對cpu,內存,網絡等資源產生必定的消耗,當這種消耗可以限定在一個可接受的範圍時,在企業內部的生產服務器上大規模部署filebeat是可行的。但若是出現一些非預期的狀況,好比佔用了大量的內存,那麼運維團隊確定是優先保障核心業務的資源,把filebeat進程給殺了。很惋惜的是,內存泄漏的問題,從filebeat的誕生到如今就一直沒有徹底解決過。(能夠區社區討論貼看看,直到如今V6.5.1都還有人在報告內存泄漏的問題)。在特定的場景和配置下,內存佔用過多已經成爲了抑止filebeat大規模部署的主要問題了。在這裏,我主要描述一下我碰到的在filebeat 6.0上遇到的問題。git
一開始咱們在不少機器上部署了filebeat,而且使用了一套統一無差異的的簡單配置。對於想要在企業內部大規模推廣filebeat的同窗來講,這是大忌!!! 合理的方式是具體問題具體分析,需對每臺機器上產生文件的方式和rotate的方式進行充分的調研,針對不一樣的場景是作定製化的配置。如下是咱們以前使用的配置:github
multiline
,多行的配置,當日志文件不符合規範,大量的匹配pattern的時候,會形成內存泄漏max_procs
,限制filebeat的進程數量,實際上是內核數,建議手動設爲1filebeat.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內存使用狀況的指標主要有兩個:web
queue.mem.events
消息隊列的大小,默認值是4096,這個參數在6.0之前的版本是spool-size
,經過命令行,在啓動時進行配置max_message_bytes
單條消息的大小, 默認值是10Mfilebeat最大的可能佔用的內存是max_message_bytes * queue.mem.events = 40G
,考慮到這個queue是用於存儲encode過的數據,raw數據也是要存儲的,因此,在沒有對內存進行限制的狀況下,最大的內存佔用狀況是能夠達到超過80G。正則表達式
所以,建議是同時對filebeat的CPU和內存進行限制。shell
下面,咱們看看,使用以上的配置在什麼狀況下會觀測到內存泄漏數據庫
對於實時大量產生內容的文件,好比日誌,經常使用的作法每每是將日誌文件進行rotate,根據策略的不一樣,每隔一段時間或者達到固定大小以後,將日誌rotate。 這樣,在文件目錄下可能會產生大量的日誌文件。 若是咱們使用通配符的方式,去監控該目錄,則filebeat會啓動大量的harvester實例去採集文件。可是,請記住,我這裏不是說這樣必定會產生內存泄漏,只是在這裏觀測到了內存泄漏而已,不是說這是形成內存泄漏的緣由。json
當filebeat運行了幾個月以後,佔用了超過10個G的內存
另外一個多是,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.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)
在6.3版本以前,咱們是沒法經過xpack的monitoring功能來觀察beats套件的性能的。所以,這裏討論的是沒有monitoring時,咱們如何去檢測filebeat的性能。固然,簡單的方法是經過top
,ps
等操做系統的命令進行查看,但這些都是實時的,沒法作趨勢的觀察,而且都是進程級別的,沒法看到filebeat內部的真是狀況。所以,這裏介紹如何經過filebeat的日誌和pprof這個工具來觀察內存的使用狀況
其實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,載入內存後,直接佔用內存固然,咱們不可能直接去讀這個日誌,既然咱們使用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
衆所周知,filebeat是用go語言實現的,而go語言自己的基礎庫裏面就包含pprof這個功能極其強大的性能分析工具,只是這個工具是用於debug的,在正常模式下,filebeat是不會啓動這個選賢的,而且很遺憾,在官方文檔裏面根本沒有說起咱們可使用pprof來觀測filebeat。咱們接下來能夠經過6.3上修復的一個內存泄漏的issue,來學習怎麼使用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
命令,查看消耗內存最多的幾個實例:
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佔用的內存過大,此時,須要仔細的確認你的上下文環境: