Day 18: 記filebeat內存泄漏問題分析及調優

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的進程數量,實際上是內核數,建議手動設爲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內存使用狀況的指標主要有兩個:web

  • 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和內存進行限制。shell

下面,咱們看看,使用以上的配置在什麼狀況下會觀測到內存泄漏數據庫

監控文件過多

對於實時大量產生內容的文件,好比日誌,經常使用的作法每每是將日誌文件進行rotate,根據策略的不一樣,每隔一段時間或者達到固定大小以後,將日誌rotate。 這樣,在文件目錄下可能會產生大量的日誌文件。 若是咱們使用通配符的方式,去監控該目錄,則filebeat會啓動大量的harvester實例去採集文件。可是,請記住,我這裏不是說這樣必定會產生內存泄漏,只是在這裏觀測到了內存泄漏而已,不是說這是形成內存泄漏的緣由。json

 

20181126205516139.png

 

當filebeat運行了幾個月以後,佔用了超過10個G的內存

 

20181126205316830.png

 

很是頻繁的rotate日誌

另外一個多是,filebeat只配置監控了一個文件,好比test2.log,但因爲test2.log不停的rotate出新的文件,雖然沒有使用通配符采集該目錄下的全部文件,但由於linux系統是使用inode number來惟一標示文件的,rotate出來的新文件並無改變其inode number,所以,時間上filebeat仍是同時開啓了對多個文件的監控。

 

20181126220013971.png

 

另外,由於對文件進行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可視化組件,清楚的看到內存泄漏的過程

 

20181127114253940.png

 

以及資源的使用狀況:

 

20181127114342557.png

 

將信息可視化以後,咱們能夠明顯的發現,內存的突變和ERR是同時發生的

 

20181127114536608.png

 

即如下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佔用了不少的內存,在圖中,展示的是調用關係棧,你能夠看到這個類是怎麼被實例化的,而且在整個堆中,內存是怎麼分佈的。最直觀的是,實例所處的長方形面積越大,表明佔用的內存越多。:

 

20181126222514954.png

 

查看源碼

經過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
相關文章
相關標籤/搜索