We just upgraded to Logstash 5.4 from Logstash 1.5.6. (Yes, we were way behind.) We're using the elasticsearch output to write to our existing ES 2.4.0 cluster. After upgrading, we're receiving a bunch of 429s from Elasticsearch caused by rejected executions from filling the bulk indexing queue.
Not sure what new/changed behavior could be causing the queues to fill. We weren't seeing this with logstash 1.5.x prior to our upgrade. Any pointers?
More details:
OS: Ubuntu 14.04.5 LTS (trusty)
Logstash Installation: debian package
Logstash runs on all end hosts using the file and udp inputs and writes directly to Elasticsearch. No filebeats or centralized logstash cluster.
Elasticsearch has 16 data nodes with 64G RAM (32G ES heap) each and 3 master nodes. No query nodes, reads directly to the masters
Ingest is spread across 8 of the data nodes and curator moves data older than a week from ingest nodes to historical nodes.
No separate query nodes; queries distributed across all 16 data nodes by DNS. (Kibana is configured with 'prd.elasticsearch.example.com:9200' which resolves to the 16 data nodes via A records.)
I know there were some changes around batching and multiple worker processes that I think could be to blame here. But hoping somebody more familiar with the changes could shed a bit more light on what's going on and how to resolve it.
(Obviously building more nodes would be one option but surely if ES could handle this ingest rate with logstash 1.5 then it should be able to do so with 5.4 as well.)
The bulk size generated from the Elasticsearch output plugin is now limited to the size of the Logstah pipeline batch size, which could have an impact. The default is 125, so I would recommend increasing this to around 1000 and see if it makes a difference.
Thanks! Sounds like a reasonable theory. If we're making a lot more requests that are all much smaller, that could quickly fill the bulk queue. I'll give it a try.
Unfortunately that doesn't solve the issue. We have logstash on all hosts in our dev and stg environments writing to one elasticsearch cluster, and uat and prod hosts writing to a second elasticsearch cluster. We're seeing issues in both clusters (429 to logstash) but I'm testing in the dev/stg cluster only.
I've confirmed that the pipeline.batch.size is 5000 on all nodes in dev/stg now:
salt '*' cmd.run '(dpkg -l | grep logstash > /dev/null) && (grep "pipeline.batch.size: 5000" /etc/logstash/logstash.yml || echo "Does not have changes")'
somehost.example.com:
pipeline.batch.size: 5000
For example, here's the log lines that we're seeing across many of our nodes:
salt '*' cmd.run 'if [ $(dpkg-query -W -f="\${Status}" logstash 2>/dev/null | grep -c "ok installed") -eq 1 ]; then tail /var/log/logstash/logstash*.log | grep 429 | grep "2017-06-07"; fi'
anotherhost.example.com:
[2017-06-07T11:22:59,123][INFO ][logstash.outputs.elasticsearch] retrying failed action with response code: 429 ({"type"=>"es_rejected_execution_exception", "reason"=>"rejected execution of org.elasticsearch.transport.TransportService$4@395eb2f3 on EsThreadPoolExecutor[bulk, queue capacity = 500, org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor@66958595[Running, pool size = 8, active threads = 8, queued tasks = 543, completed tasks = 461130777]]"})
We've already upped the queue capacity to 500 in the cluster, as you can see above.
I've even shut down logstash on all nodes in dev. Stg nodes are still getting 429 back to their logstash.
For what its worth, we have 137 nodes running logstash in dev and 50 nodes running logstash in stg.
Any more ideas? Something I can do to get more details or troubleshoot the problem?
Just did a tcpdump and confirmed that we're seeing only a few events per bulk request.
Next theory: we have a lot of workers that are splitting the events across them causing a small bulk request payload. (It's not unusual for us to have 20-60 cores on a host). Going to set workers to 1 and see if that increases the number of events per request size.
Do you by any chance have a large number of elastic search outputs to different indices configured? As each internal batch is processed as a unit, having multiple elasticsearch outputs can mean that a separate bulk request is generated for each output, resulting in more, smaller bulk requests.
Oh that's a good point I hadn't considered yet. Most hosts have 2 elasticsearch outputs. A handful of hosts (maybe 15-20%) have between 3 and 5 elasticsearch outputs. All outputs on a host hit the same cluster but different indices.
One way to allow a single elasticsearch output to index into multiple, different index patterns is to create the prefix (or even full index name) in the filter section and store this in the event metadata. This can then be referenced in the elasticsearch output when the index name is created.
We actually have them split into separate files per pipeline right now with all three input/filter/output sections. (well, not the official "pipelines" that are coming out) But we could consider that as a next step.
After applying the pipeline.workers=1 change across all nodes in dev and stg, it appears that I'm not getting 429s anymore yet... but it hasn't been very long since I restarted them all. Would this make sense conceptually/theoretically given what you know of how logstash operates?
This blog post describes the evolution of output workers and might be useful. Changing the number of pipeline workers to 1 will have a negative impact on processing throughput, so I would recommend increasing it, although maybe not quite to the default value as this was causing problems.
Another idea would be to create a tiered ingest pipeline where one set of Logstash instances do all the processing and a separate set are responsible for just writing data to Elasticsearch as efficiently as possible. This would probably result in larger batches and fewer total connections.
Just finished reading that post myself. Very useful, thanks!
I don't think we're throughput constrained on a single logstash instance (since we have one per host), but I do recognize that workers=1, batch size=5000 is probably going to have some of its own issues. Once the fires are out and we know this works to give us visibility again in prod, I'll probably try tuning that to workers=1, batch=1000 or workers=5, batch=1000.
The long term plan is definitely to create a tiered pipeline with filebeats and logstash. It certainly seems like that our particular setup is more of anomaly (or relic) at this point. Just didn't want to make the ES 5 upgrade dependent on replacing logstash with filebeats on all of our hosts.
Apache, Apache Lucene, Apache Hadoop, Hadoop, HDFS and the yellow elephant
logo are trademarks of the
Apache Software Foundation
in the United States and/or other countries.
