90k files amount - cleaning registry too slow?

Elastic Stack Beats
1

Hi,
It's bit frustrating to understand what is Filebeat doing during startup. My situation is, I needed to ingest about 90k files from fs, which were simple xml logs. It happend quite fast. No problems at all.
Afterwards, filebeat.yml was limited to ingest only files not older thant 3 days (about 10k of files). However, filebeat is starting for more than 3 hours without sending new logs to logstash. Only records in log file are, lines like this:

2020-11-16T17:11:12.734+0100	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":594515,"time":{"ms":3344}},"total":{"ticks":7365186,"time":{"ms":27140},"value":7365186},"user":{"ticks":6770671,"time":{"ms":23796}}},"handles":{"open":199},"info":{"ephemeral_id":"0eedf066-8019-4711-bb27-1c57570f73b2","uptime":{"ms":8670060}},"memstats":{"gc_next":326789872,"memory_alloc":234747080,"memory_total":1135321850328,"rss":27598848},"runtime":{"goroutines":21}},"filebeat":{"events":{"added":84,"done":84},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":1,"filtered":84,"total":84}}},"registrar":{"states":{"current":95781,"update":84},"writes":{"success":84,"total":84}}}}}

My filebeat.yml is:


  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    #- /var/log/*.log
    - E:\tmp\duplicate_response\*\*.xml

  ### Multiline options
  multiline.type: pattern
  multiline.pattern: '^<\?xml'
  multiline.negate: true
  multiline.match: after
  
  close_eof: true
  clean_inactive: 72h
  clean_removed: true
  ignore_older: 70h

The question is, when it will end "reindexing" of the registry file? File has 25MB and is growing...

2

Just for the record for somebody else:
The filebeat cached in first run 95.000 files. That is the log mess for a about 10 days.
Second run, after setting "clean_inactive: true" and "ignore_older: 70h" it went through those 95k files with tempo 85 files per 30secs. In overall, 6hours to start harvest. Afterwards, everything works, however, filebeat takes constantly 10% from CPU performance, which is compared to other instances (0-1%), big difference. During the "start procedure", CPU didn't step over 15%. Register has close to 30MB.
This is in the log:

2020-11-17T00:33:42.905+0100	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2719703,"time":{"ms":1969}},"total":{"ticks":30589749,"time":{"ms":25922},"value":30589749},"user":{"ticks":27870046,"time":{"ms":23953}}},"handles":{"open":200},"info":{"ephemeral_id":"0eedf066-8019-4711-bb27-1c57570f73b2","uptime":{"ms":35220060}},"memstats":{"gc_next":430127152,"memory_alloc":349032104,"memory_total":5567058280584,"rss":-34897920},"runtime":{"goroutines":21}},"filebeat":{"events":{"added":82,"done":82},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":1,"filtered":82,"total":82}}},"registrar":{"states":{"current":95781,"update":82},"writes":{"success":82,"total":82}}}}}
2020-11-17T00:34:12.908+0100	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2721750,"time":{"ms":2047}},"total":{"ticks":30616015,"time":{"ms":26266},"value":30616015},"user":{"ticks":27894265,"time":{"ms":24219}}},"handles":{"open":200},"info":{"ephemeral_id":"0eedf066-8019-4711-bb27-1c57570f73b2","uptime":{"ms":35250060}},"memstats":{"gc_next":429710576,"memory_alloc":342184552,"memory_total":5572227708192,"rss":-10797056},"runtime":{"goroutines":21}},"filebeat":{"events":{"added":82,"done":82},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":1,"filtered":82,"total":82}}},"registrar":{"states":{"current":95781,"update":82},"writes":{"success":82,"total":82}}}}}
2020-11-17T00:34:42.907+0100	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2724062,"time":{"ms":2312}},"total":{"ticks":30641780,"time":{"ms":25765},"value":30641780},"user":{"ticks":27917718,"time":{"ms":23453}}},"handles":{"open":199},"info":{"ephemeral_id":"0eedf066-8019-4711-bb27-1c57570f73b2","uptime":{"ms":35280061}},"memstats":{"gc_next":430085072,"memory_alloc":394263432,"memory_total":5576885581592,"rss":-44417024},"runtime":{"goroutines":21}},"filebeat":{"events":{"added":79,"done":79},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":1,"filtered":79,"total":79}}},"registrar":{"states":{"current":95781,"update":79},"writes":{"success":79,"total":79}}}}}

I am bit curious if there is any correlation with "close_inactive" and "clean_inactive" even if I'm using "close_eof: true"? Consequent question would be, how to shrink registry automaticaly?

3

More news:
Filebeat Registry file shrink automatically during the time as the overall amount of files changed (less files on the storage). Starting is more convenient now, as well as CPU load. Simply, too many files is not what Filebeat likes, it's better to have more instances of it as well as limit sources with close_eof, clean_inactive, clean_removed and ignore_older option.

4

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.