Performance degradation after upgrading from version 1.5 to 5.2

Elastic Stack Elasticsearch
1

Hello,

Recently we upgraded our elasticsearch instance from version 1.5 to version 5.2 and we have noticed significant increases in the response times of our application calls to elasticsearch for document updates. The client we use for making these updates is a org.elasticsearch.client.Client instance and the way we use it for making the updates is this:

			client.prepareUpdate(...)
					.setScript(new Script(ScriptType.INLINE, Script.DEFAULT_SCRIPT_LANG, ...))
					.setUpsert(theUpsertDoc)
					.setRetryOnConflict(3)
					.get();

When running with elasticsearch 1.5, the average response time of this call was approximately 3-5 milliseconds per request, using 150 concurrent threads. After the elasticsearch upgrade to 5.2 the average response time of this call with the same concurrency level (150 threads) increased to 50 milliseconds per request. It's worth to mention that in our initial load tests this average was at about 85 milliseconds per request, and after changing the index setting transcript.durability to async we saw that the time was improved to 50 milliseconds per request. Furthermore, it seems that this performance issue manifests itself when the request concurrency is high.

Given the above situation, we would like to see our possible options on how to handle this performance degradation issue. Are there any configuration tweaks we can make either on the server side or the client side to improve this performance issue? Also, is there some explanation why the performance of the above request we are using degraded so much after the upgrade to 5.2?

Thanks

2

It depends on what you are doing. It is really best to have a look at hot_threads or jstack on a node while you are doing the update rather than guessing.

But I can't resist guessing. If you happen to be updating the same document very quickly you might hit a case where Elasticsearch has to perform a refresh to support a realtime get of the document. We made this change to support some other optimizations to what we thought was a more common case, indexing many distinct documents without updates.

3

Hi again,

I'd just like to share some more details regarding our use case:

  • Documents in elasticsearch are created and updated using the same code block I sent in my previous post
  • Indeed a newly created document is quickly updated several times (7-10 times depending on our different load test scenarios) during the next milliseconds after its creation. These updates typically are not executed concurrently, although there might be cases where some updates of the same document might be sent concurrently to elasticsearch.

Also, some findings from our latest tests:

  • Using 3 nodes in the elasticsearch cluster we see that the average time per update is about 55-60 milliseconds. We tried increasing the cluster nodes to 4 but saw no significant improvement. However, when we increased the cluster nodes to 5 we saw the average time per update dropped to about 30 milliseconds. Just to compare with the elasticsearch version 1.5 I should mention that on a cluster of 3 nodes the average time per update was about 5 milliseconds on version 1.5.

  • As you advised, I used the hot_threads API during the load tests execution to try to figure out bottlenecks on elasticsearch. Most times the hot thread API returned something like this on the first node:

::: {mdvmsrv459}{ad82Eq-DRLONhRToWJ_omg}{TQOjHGlAQZ6FKIMd5Ayz0w}{10.99.232.45}{10.99.232.45:9300}
Hot threads at 2017-05-04T10:54:21.911Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

   73.6% (367.7ms out of 500ms) cpu usage by thread 'elasticsearch[mdvmsrv459][[cvp_tst_user_idx_2][2]: Lucene Merge Thread #1417]'
     2/10 snapshots sharing following 12 elements
       org.apache.lucene.codecs.lucene54.Lucene54DocValuesConsumer.addNumericField(Lucene54DocValuesConsumer.java:89)
       org.apache.lucene.codecs.lucene54.Lucene54DocValuesConsumer.addSortedNumericField(Lucene54DocValuesConsumer.java:589)
       org.apache.lucene.codecs.DocValuesConsumer.mergeSortedNumericField(DocValuesConsumer.java:470)
       org.apache.lucene.codecs.DocValuesConsumer.merge(DocValuesConsumer.java:243)
       org.apache.lucene.codecs.perfield.PerFieldDocValuesFormat$FieldsWriter.merge(PerFieldDocValuesFormat.java:153)
       org.apache.lucene.index.SegmentMerger.mergeDocValues(SegmentMerger.java:167)
       org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:111)
       org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4343)
       org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3920)
       org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
       org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:99)
       org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)
     4/10 snapshots sharing following 8 elements
       org.apache.lucene.codecs.lucene60.Lucene60PointsWriter.merge(Lucene60PointsWriter.java:215)
       org.apache.lucene.index.SegmentMerger.mergePoints(SegmentMerger.java:173)
       org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:122)
       org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4343)
       org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3920)
       org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
       org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:99)
       org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)
     2/10 snapshots sharing following 26 elements
       sun.nio.ch.FileDispatcherImpl.write0(Native Method)
       sun.nio.ch.FileDispatcherImpl.write(FileDispatcherImpl.java:60)
       sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
       sun.nio.ch.IOUtil.write(IOUtil.java:65)
       sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:210)
       java.nio.channels.Channels.writeFullyImpl(Channels.java:78)
       java.nio.channels.Channels.writeFully(Channels.java:101)
       java.nio.channels.Channels.access$000(Channels.java:61)
       java.nio.channels.Channels$1.write(Channels.java:174)
       org.apache.lucene.store.FSDirectory$FSIndexOutput$1.write(FSDirectory.java:419)
       java.util.zip.CheckedOutputStream.write(CheckedOutputStream.java:73)
       java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
       java.io.BufferedOutputStream.write(BufferedOutputStream.java:95)
       org.apache.lucene.store.OutputStreamIndexOutput.writeByte(OutputStreamIndexOutput.java:47)
       org.apache.lucene.store.RateLimitedIndexOutput.writeByte(RateLimitedIndexOutput.java:66)
       org.apache.lucene.codecs.lucene53.Lucene53NormsConsumer.addByte1(Lucene53NormsConsumer.java:101)
       org.apache.lucene.codecs.lucene53.Lucene53NormsConsumer.addNormsField(Lucene53NormsConsumer.java:81)
       org.apache.lucene.codecs.NormsConsumer.mergeNormsField(NormsConsumer.java:134)
       org.apache.lucene.codecs.NormsConsumer.merge(NormsConsumer.java:96)
       org.apache.lucene.index.SegmentMerger.mergeNorms(SegmentMerger.java:179)
       org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:133)
       org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4343)
       org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3920)
       org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
       org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:99)
.... [truncated lines]

So given our use case details and the above findings, do you think there is a way to make the performance of updates on version 5.2 similar to the performance we had observed on version 1.5? In your last post I didn't quite get this phrase you mentioned:

If you happen to be updating the same document very quickly you might hit a case where Elasticsearch has to perform a refresh to support a realtime get of the document

Wasn't that the case in version 1.5 as well in order to support the realtime get? Or has this changed somehow on 5.2?

Thanks

4

Hi once again,

In an attempt to shed some more light into this issue, I'd like to clarify that the performance issue is easily reproducible by simply having some client threads invoking the code snippet I've shared in my first post for upserting documents in the elasticsearch index. If you measure the time of each update on elasticsearch version 1.5 and 5.2 you'll see that the times in 5.2 are much much slower.

The way I'm reproducing the issue is with jmeter, using a pool of 100 threads each of which makes 4 HTTP calls: the first 3 are upserting the same document (the first call creates the document and the other 2 are updating it), and the fourth call is reading it. I'm having each thread repeat these calls for 200 times (each repeat uses a new document for upserting/reading). So this test makes 60000 upsert and 2000 read calls to elasticsearch.

Running this test on elasticsearch 1.5 gives me an average of 2 milliseconds for each upsert call and an average of 1,5 milliseconds for each read call.
Running the same test on elasticsearch 5.2 gives me an average of 53 milliseconds for each upsert call and an average of 34 milliseconds for each read call.

I also tried to remove the script from the upsert calls as the documentation suggests that it imposes performance overhead, so I tried making the upserts like this:

	IndexRequest indexRequest = new IndexRequest(elasticsearchProperties.getUserIndex(), type, String.valueOf(id))
			.source(upsertDoc);
	UpdateRequest updateRequest = new UpdateRequest(elasticsearchProperties.getUserIndex(), type, String.valueOf(id))
			.doc(upsertDoc)
			.upsert(indexRequest);
	client.update(updateRequest).get();

However, I didn't see any improvement. Nevertheless, I did notice that when using documents in this call that were identical with documents that were already in the index, the calls were super fast (they took time simliar to the upsert call on elasticsearch 1.5). When using the script these calls were slow.

Lastly, one comment regarding the concurrency of the upsert calls on 5.2 is that when I used less jmeter threads to run to above test scenario, I could see that the average times per request were dropping: using 5 threads the average time of each upsert was 12 milliseconds and the average time of each read was 8 milliseconds

I hope that now it's more clear under which circumstances this performance issue appears and I hope it's easier to identify the potential root causes of it. Any ideas what we can do for dealing with this issue?

Thanks!

5

No. This changed in order for us to optimize a different path. There aren't settings in Elasticsearch that you can change to get the 1.5 behavior back.

While we support updating documents very quickly after it has just changed it isn't fast. We used to be faster but that required that we do things that are inefficient when you bulk load without specifying an ID. The old behavior isn't coming back because we consider this constant updating to be less important then the bulk loading and it is optimize one or the other.

The only way to get your performance back is to coalesce these updates yourself.

6

So, if I understand correctly, your suggestion is either to use the Bulk API for sending the document updates with bulks, or somehow gather all the updates of the same document (the ones that are currently executed separately and quickly the one after the other) and send them all together as one document upsert request, am I getting this right?

In our platform we have several webapps/modules that talk with each other using the rabbitmq message broker. In our business flows there are cases where a module receives a rabbitmq message, makes an elasticsearch document update and dispatches a rabbitmq message that another module will listen and try to read the document that was updated shortly before.

Given this setup, if we use the Bulk API for issuing the document updates we'll bump into the problem where the module that tries to read the updated document will not see the updates that were applied shortly before. On the other hand, gathering all the same document updates and send them all together as one document upsert request will require a major redesign and changes in many of our modules.

Is there any other suggestion that you think could meet our update/read requirements on elasticsearch 5.2 without imposing such a performance overhead?

Thanks for your valuable feedback!

7

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