Filebeat - logstash performances troubleshooting

Hello,

I have an application which generates ~50 files/minute with 10000 events (monoline). Previously, I read these files with logstash, processed them and sent them to Elasticsearch. Unfortunately, I was CPU-bound, so I bought fresh new servers dedicated for logstash.

Now, I have:

  • 1 app server which generates events and send them to logstash with filebeat
  • Another app server (same hardware) which generates events and send them to elasticsearch (via a local logstash 2.4 instance with file input)
  • 1 logstash server (5.2 or 2.4, I tested both) which send events to elasticsearch.

Elasticsearch cluster is 5.1.

Once created, my log files are never updated.

The issue is that performances are far worse with the filebeat/logstash configuration than with the file input/logstash configuration (~9000 event/second vs 5000 event/s)

I don't have any RAM/CPU/IO/network issue on the filebeat/logstash stack.

With the following configuration, I send ~100 000 events in 30s (~3300 event/s). My goal is to achieve between 20000 and 30000 event/s on the filebeat/logstash part.

filebeat.prospectors:
- document_type: netflow_in
  ignore_older: 1h
  input_type: log
  paths: [/tmp/FLOW_IN/*/*/*/*/*.flows]
  scan_frequency: 1s
  harvester_buffer_size: 131072
  close_eof: true
  clean_removed: true
  close_inactive: 10m
- document_type: netflow_out
  input_type: log
  ignore_older: 1h
  paths: [/tmp/FLOW_OUT/*/*/*/*/*.flows]
  scan_frequency: 1s
  harvester_buffer_size: 131072
  close_eof: true
  clean_removed: true
  close_inactive: 10m
logging.files: {keepfiles: 3, name: filebeat, path: /var/log/filebeat, rotateeverybytes: 10485760}
logging.level: info
logging.metrics.enabled: true
logging.metrics.period: 30s
logging.to_files: true
output.logstash:
  hosts: ['elkprod-netflow-logstash-tc2.priv.sewan.fr:10010']
filebeat.spool_size: 16384
queue_size: 2000

Queue size, spool_size, harvester_size don't seem to have any effect at all.

Here is what I get:

2017-03-01T18:57:05+01:00 INFO Non-zero metrics in the last 30s: registrar.states.cleanup=370 registrar.states.update=92070 publish.events=81920 filebeat.harvester.open_files=1053 filebeat.harvester.running=1054 libbeat.logstash.call_count.PublishEvents=44 libbeat.logstash.publish.read_bytes=258 registar.states.current=7444 libbeat.logstash.published_and_acked_events=81902 libbeat.publisher.published_events=82813 filebeat.harvester.started=1054 libbeat.logstash.publish.write_bytes=5670331 registrar.writes=6

When I loadbalance on 4 ports on my 2.4 logstash, with 10 filebeat workers (I am really not CPU-bound, so...), it's slightly better, but far from what I'd expect

2017-03-01T18:58:56+01:00 INFO Non-zero metrics in the last 30s: registar.states.current=31 libbeat.logstash.published_and_acked_events=147435 libbeat.logstash.publish.read_errors=7 libbeat.logstash.published_but_not_acked_events=14333 libbeat.logstash.publish.write_bytes=10246957 libbeat.logstash.call_count.PublishEvents=87 publish.events=147456 registrar.writes=10 filebeat.harvester.running=24 filebeat.harvester.started=24 filebeat.harvester.open_files=24 registrar.states.update=160691 libbeat.logstash.publish.read_bytes=846 libbeat.publisher.published_events=163815

My logstash conf:

input {
        beats {
                port => 10010
        }
        beats {
                port => 10011
        }
        beats {
                port => 10012
        }
        beats {
                port => 10013
        }
}

filter {
        drop {}
}
output{
elasticsearch {
                       index => "logstash_netflow_client_v12-%{+YYYY.MM.dd}"
                       hosts => ["http://host1",http://host2, http://host3,http://host4, http://host5,http://host6, http://host7, http://host8]
                       flush_size => 250
                       workers => 40
}

Logstash is launched with -b250. As you can see, in order to be sure that I don't have any issue with Elasticsearch, I just drop anything.

On both servers, I have 70% idle CPU and no iowait. I disabled swap too, and still have at least half my RAM.

I really fail to see the issue there.

Do you have an idea how could I troubleshoot that furthermore. Is there an issue with the metrics shown by Filebeat ?

Thank you,
Regards,
Grégoire

Please use </> button to format logs and configs.

Can you post a more complete filebeat configuration?

  1. have you tried logstash 5.x? Or have you tried to update the logstash-input-beats plugin to version 3.1.10 (... seems to be most stable version so far)? The logstash-input-beats plugins 3.1.x is a rewrite in java with slight performance improvements AFAIK.

  2. Have you checked filebeat logs instead of just looking at metrics? These stats libbeat.logstash.publish.read_errors=7 libbeat.logstash.published_but_not_acked_events=14333 suggest logstash dropping the connection. As many events get not ACKed as get send. On connection drop, a worker might back-off (e.g. 1 second with exponential backoff)... having some impact on throughput.

  3. I don't think you need mulitple ports to parallelize the tasks. just increase worker setting in filebeat. the spool_size should be a multiple of bulk_max_size * worker, so events can be split into batches.

  4. did you try the async settings in filebeat logstash output (in conjunction with load-balancing and very big spooler size to create small high number of smaller batches to be pipelined)?

  5. did you try filebeat->console or file output to check how fast filebeat can read and publish events?

Actually, that's my whole configuration, I guess everything else are the defaults, but if you want I can have a more explicit configuration.

Yes, that was the first version I used. I have just re-upgraded to 5.2 now and I have these results, with 20 workers:

2017-03-02T14:34:08+01:00 INFO Non-zero metrics in the last 30s: libbeat.logstash.publish.read_bytes=366 libbeat.logstash.published_and_acked_events=124893 libbeat.publisher.published_events=131032 registrar.writes=8 libbeat.logstash.call_count.PublishEvents=62 libbeat.logstash.publish.write_bytes=8743005 filebeat.harvester.running=41 publish.events=114688 registar.states.current=40 filebeat.harvester.started=41 registrar.states.update=120131 filebeat.harvester.open_files=39

From what I see, I have no libbeat.logstash.published_but_not_acked_events, now.

I have nothing really interesting. Mainly things like 2017-03-02T14:41:03+01:00 INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /tmp/path/to/data/30-4_26092.flows
And I have logs of harvester files opening. Well, I guess the message is no big deal, it just means that my current configuration can not handle the load and so that old files are not fully harvested

What's the default bulk_max_size for logstash (or file) output ? From what I see in filebeat.full.yml, it's a parameter for ES, Kafka and Redis outputs only.

Well, just setting the async at true, without load-balance has a nice effect : I reach ~200 000 events for 30s.

I did now (file output, no IO issues, 60 files rotation), it seems I have the same results than with logstash:
2017-03-02T14:59:21+01:00 INFO Non-zero metrics in the last 30s: filebeat.harvester.running=42 filebeat.harvester.started=42 libbeat.publisher.published_events=196570 filebeat.harvester.open_files=42

Setting the async parameter at false, I get ~100 000 events for 30s (as with logstash output).

When I increase spool_size a lot (163840), I have 100 000 events/30s, whatever the async parameter.

If I understand correctly the results of the tests:

  • My issue is not related to logstash, as I have the same results with file output or logstash output
  • The only parameter which helped me handle the load so far is pusblish_async, which when activated, allows me to go beyond 200 000 event/30s. (spool_size is 16384)

However, I have 2 issues, with that:

  • The memory usage does not stop to increase, and I finish being Out Of memory.
  • 200 000 events/30s is still not enough to handle the load.

Is there another thing I should see ? Here is my full filebeat configuration:

filebeat.prospectors:
- document_type: netflow_in
  ignore_older: 1h
  input_type: log
  paths: [/tmp/FLOW_IN/*/*/*/*/*.flows]
  scan_frequency: 1s
  harvester_buffer_size: 131072
  close_eof: true
  clean_removed: true
  close_inactive: 10m
- document_type: netflow_out
  input_type: log
  ignore_older: 1h
  paths: [/tmp/FLOW_OUT/*/*/*/*/*.flows]
  scan_frequency: 1s
  harvester_buffer_size: 131072
  close_eof: true
  clean_removed: true
  close_inactive: 10m
logging.files: {keepfiles: 3, name: filebeat, path: /var/log/filebeat, rotateeverybytes: 10485760}
logging.level: info
logging.metrics.enabled: true
logging.metrics.period: 30s
logging.to_files: true
output.file:
  path: "/tmp/filebeat"
  filename: filebeat
  number_of_files: 60
filebeat.spool_size: 16384
queue_size: 2000
filebeat.publish_async: true

Regards,
Grégoire

The memory issue is probably cause by publish_async. It allows higher speeds but at the cost of memory usage when the output does not keep up with the reading speed.

You said you have the same result when writing to disk or logstash. I would expect higher speeds writing to disk except when your disk cannot keep up. What kind of disks do you use? What is the size of the events you have? Because number of events alone does not tell enough.

Hello,

The size of my events is 143 octets (it varies between 120 and 200 octets) . I tried to use a console output with a redirection to /dev/null and I have roughly the same amount of processed events (between 190000 and 220000).

I use SSD and I don't see any issue with disks; iowait are 0:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
      25.74    0.00    3.16    0.00    0.00   71.10

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sdb               0.00         0.00         0.00          0          0
sda              12.00       256.00      5324.00        256       5324
dm-0             12.00       256.00      5324.00        256       5324
dm-1              0.00         0.00         0.00          0          0

Here is the result of a ioping:

--- /dev/mapper/centos-root (block device 100.1 GiB) ioping statistics ---
59 requests completed in 58.9 s, 997 iops, 3.90 MiB/s
min/avg/max/mdev = 130 us / 1.00 ms / 25.9 ms / 4.03 ms

It seems that the issue is not related to the output (as with console, disks or logstash I have the same throughput), so I guess that it's related to the input ?

I tried to increase the harvester_buffer_size parameter : all my files are 1.4Mo, so I figured I could read them just once, store them in memory and process them (they are never updated after), but it does not have any good impact on the metrics.

I tried to increase the number of prospectors too, without any success.

I really fail to see the bottleneck there.

Regards,
Grégoire

The harvesters/prospectors reading files do run in parallel. But the publisher pipeline between filebeat and output itself does not.

With filebeat going OOM with publish_async is enabled, indicates events being read faster, then the outputs can consume. Feature has been experimental and will be replaced in future with some 'always' async, but bounded queue. Still, async processing will only help with reducing latencies in outputs. Without publish_async the latencies come from:

  1. flush events
  2. encode events
  3. in logstash case by default compress events (you can try to reduce latency by disabling compression)
  4. encrypt if 'TLS' is eanbled
  5. send events
  6. wait for ACK from logstash
  7. signal filebeat/pipeline the most recent batch has been consumed.

Without publish_async, the spooler will be cleared only after this complete processing took place. The latencies in publishing one batch unfortunately affects all output workers and filebeat.

Btw. when saying async, I originally did mean pipelining setting in logstash output. This one tries do reduce network latencies, but running the json-encoding, sending and waiting for ACK all concurrently (requires logstash 5.x). This plus publish_async might get you the highest throughput.

Another potential bottleneck in filebeat is the one spooler in filebeat itself. The single-spooler-strategy enforces all processing of events (internal transformation) to be published being executed in one-thread only, besides potentially parallelizable. Also something I hope to address when improving the filebeat spooler/publisher pipeline.

You're benchmarks do show only event throughput, but not memory/CPU usage (maybe some other interesting metrics). If filebeat resource usage is much lower then it should be, you can try to run another filebeat process instead of configuring another prospector. But then I wonder how OS-threads filebeat is using (e.g. did you set GOMAXPROCS by accident?).

Filebeat throughput also depends on the machine itself. e.g., are you running filebeat in VMs or host?

But in general, the console output to /dev/null should give you an idea how many events one instance can currently process at max (what's CPU/memory usage here?).

Hello,

I may have found the issue. As you can see in the configuration, the ignore_older is 1h. My files are in path like "/tmp/FLOW_IN/year/month/day/hour/minutes-id.flows".

With the configuration above, I'm limited to 200 000 event/30s max. When I change paths for paths: ["/tmp/FLOW_OUT/2017/03/06/12/*.flows"] (idem for FLOW_IN), I reach until 1,5 million events/30s.

Here is the result of top:

top - 12:56:57 up 376 days, 35 min,  1 user,  load average: 4.79, 3.14, 2.10
Tasks: 247 total,   2 running, 245 sleeping,   0 stopped,   0 zombie
%Cpu(s): 21.6 us,  1.2 sy,  0.0 ni, 76.4 id,  0.0 wa,  0.0 hi,  0.8 si,  0.0 st
KiB Mem :  7876588 total,   159624 free,  3364212 used,  4352752 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  3730452 avail Mem

As you can see, I don't have a CPU/RAM issue. Do you have an idea where this issue come from ?

Meanwhile, I can work it around in changing the filebeat configuration everyday with a script but it'd be way cleaner if I could debug it without that.

Regards,
Grégoire

Hello,

Should I fill an issue on github about this behaviour or is it expected ?

Regards,
Grégoire

One potential reason why your system uses that much memory / cpu is that you have a very low scan_frequency number so it constantly scans your file system which also affects the disk. This can especially have an affect if you have a large number of files. Can you check if this makes a difference?

What is the total number of files touched by your prospectors?

So, you managed to send 500k events/s?

filebeat is trying to process files concurrently. That is, when using *.flows, you have a higher chance to process yet missing files. You also have a quite 'low' scan_frequency of just 1sec. That is, with configuring "/tmp/FLOW_OUT/*/*/*/*/*.flows" and having a many directories/files, the scanning requires more time + more checks. When checking files, the prospector must check/validate against running harvesters + internal state updates. Having too many checks too fast might create some contention between these 3 processes: harvesters, state update, prospector scans. By using "/tmp/FLOW_OUT/2017/03/06/12/*.flows", you potentially highly reduce the search-space and thusly reduce contention, allowing you data+internal state updates happening much faster. One potential enhancement that might help is having filebeat to not actively search for changes, but listen for changes via inotify (inotify support on the other hand might introduce it's own issues, e.g. network shares, file truncates on older kernels, ...). We're introducing prospector config reloading via conf.d directory. One can basically put a prospector configuration in this directory and filebeat will dynamically pick this up. A cron-job might add/remove prospectors from this directory.

Another note about the kind of contention described: the contention is only present between prospector/harvester/spooler. Having multiple prospectors with mostly one being active (and one potentially picking up old files), there will be no contention in between harvesters. That is, conf.d plus more specific paths (like "/tmp/FLOW_OUT/2017/03/06/12/*.flows") might be a viable workaround.

Hello,

Well, it's more 50k event/seconds but at that point, logstash becomes the bottleneck instead of filebeat.

I noticed that a big registry (~10 Mo) can significantly slow down the filebeats performances.

The workaround I had these days was to use two filebeat instances (one current and one "old"), and only work on 2 hours, I measured it was more performant than 2 prospectors. I dynamically (cron-job) change the conf of both filebeat instances everyhour and restart them (and I clean/copy the registry).

The algo is:

  1. Stop nicely both filebeat instances (i.e systemd stop)
  2. Modify the path in prospectors
  3. Move the current filebeat registry to the old instance
  4. Start both filebeat

The issue with my workaround is that I observe huge spikes of events every hour at XX:59 and XX:00 (based on the timestamp located in files, not the processing timestamp), which seems to indicate a lot of duplicates (in my data source, I don't have more events at these times). I'm very curious to know why as I take care of keeping the registry.

I tried to add the parameter "shutdown_timeout" at an high value (30s), without any impact.

I somehow missed the conf.d feature, so i'm going to try it now. I noticed that the reload will only come in 5.3, I'll probably try the nightly build if the restart does not work as expected.

Thank you,
Regards,
Grégoire

Is using clean_inactive an option for you? That would keep your registry down. Do the files you write ever change?

Hello,

My files are dumped one time and never updated after. Here is an example of prospector (current.yml):

filebeat.prospectors:
- clean_removed: true
  close_eof: true
  close_inactive: 10m
  document_type: netflow_in
  exclude_lines: [^FLOW_END_SEC]
  ignore_older: 2h
  input_type: log
  paths: [/tmp/FLOW_IN/2017/03/16/12/*.flows]
  scan_frequency: 59s
  clean_inactive: 130m

Every hour, this prospector file is changed to reflect the new current hour and the content of this file is copied in an old.yml.

What I get is an always increasing registry file with entries about removed files and files supposed to be cleaned. As I restart filebeat every hour, I get duplicates of all my events. So, it seems that the clean_ directives don't work at all.

Did I miss a clean/close parameter in this configuration ?

A theory is that as my prospector is totally modified, the clean_* directives are not applied for paths which are now non-existent. Is that a likely outcome ?

Thank you,
Regards,
Grégoire

Hello,

In order to check this theory, I changed my cron jobs to have the following behaviour:

At any moment, I have 3 prospectors whose the name is hh.yml; hh being the current hour, h-1 or h-2. For example, now I have 16.yml, 15.yml and 14.yml. My prospectors is like what I pasted above, only the paths change.

Expected behaviour:
At 4pm, when my cronjob is activated, I delete 13.yml, and create 16.yml. 14.yml and 15.yml remain the same and I restart filebeat. At 16:55, every registry entry for flows before 14h05 should have been cleaned (cleaned_inactive : 130m).

Furthermore, I should not have any duplicates, the registry is there to prevent it.

Actual behaviour : I still have a lot of duplicates.

Furthermore, in the registry, I still have entries for 14:20 or even 13:17. (Note : it's 16:48 right now so even 14:20 should have been cleaned from the registry).

I really struggle to see what's the issue there...

Regards,
Grégoire

The problem is that you are restarting filebeat. The cleanup of the registry is triggered by the prospectors. In case no prospector is responsible for the file, a cleanup will not happen to make sure not states are removed by accident. So in case you would keep around the old prospector config, the states should be cleaned up properly.

The upcoming 5.3 release will have a reload feature for filebeat prospectors: https://www.elastic.co/guide/en/beats/filebeat/5.x/filebeat-configuration-reloading.html This should become quite handy in your case. This will remove the need for your constant restarts and should also solve your problem with the duplicated events. With you config above, you must make sure that the prospector for the files is around for at least 130 minutes after the files finished reading.

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