RestHighLevelClient low performance when indexing

[xavierfacq]

Hi,

I'm refactoring our code to migrate from Transport Client to RestHighLevelClient.
I do not have monitored searches at now but I have problems during indexations.
Indexation are super longer than with the Transport Client.

Version
Cluster nodes and client are in version 6.6.1

JDK:
openjdk version "1.8.0_201"
OpenJDK Runtime Environment (build 1.8.0_201-b09)
OpenJDK 64-Bit Server VM (build 25.201-b09, mixed mode)

OS:
Linux BP-PRD-SFX13 3.10.0-957.5.1.el7.x86_64 #1 SMP Fri Feb 1 14:54:57 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

`My first mesure of performance are duration of the full process of indexation:

Indexing type 1:
Transport Client: P0Y0M0DT1H23M13.066S / P0Y0M0DT1H26M31.467S
RestHighLevelClient: P0Y0M0DT2H42M54.303S

For this index, time is x2 !

Indexing type 2:
Transport Client: P0Y0M0DT2H38M5.045S / P0Y0M0DT2H37M46.819S / P0Y0M0DT2H40M22.611S / P0Y0M0DT2H36M23.148S
RestHighLevelClient: P0Y0M0DT4H21M7.071S / P0Y0M0DT4H16M25.221S / P0Y0M0DT4H6M15.441S

For this one we are at ~2h40 with the Transport Client and ~4h15 with RestHighLevelClient

Another mesure is the index rate every 30 minutes

Transport Client:
INFO: >>> Indexation progress: Total nbQueuedElements = 16635825 / Total nbIndexedElements = 16529138 / Total QueueingRate = 9242 elements/sec / Loop nbQueuedElements = 16635817 / Loop nbIndexedElements = 16529138
INFO: >>> Indexation progress: Total nbQueuedElements = 102867389 / Total nbIndexedElements = 102800459 / Total QueueingRate = 28574 elements/sec / Loop nbQueuedElements = 86231522 / Loop nbIndexedElements = 86271321

RestHighLevelClient :
INFOS: >>> Indexation progress: Total nbQueuedElements = 15812209 / Total nbIndexedElements = 15592210 / Total QueueingRate = 8784 elements/sec / Loop nbQueuedElements = 15812209 / Loop nbIndexedElements = 15592210
INFOS: >>> Indexation progress: Total nbQueuedElements = 33418351 / Total nbIndexedElements = 33218352 / Total QueueingRate = 9282 elements/sec / Loop nbQueuedElements = 17606142 / Loop nbIndexedElements = 17626142
INFOS: >>> Indexation progress: Total nbQueuedElements = 54120571 / Total nbIndexedElements = 53951028 / Total QueueingRate = 10022 elements/sec / Loop nbQueuedElements = 20702217 / Loop nbIndexedElements = 20732676
INFOS: >>> Indexation progress: Total nbQueuedElements = 75133642 / Total nbIndexedElements = 74944797 / Total QueueingRate = 10435 elements/sec / Loop nbQueuedElements = 21013063 / Loop nbIndexedElements = 20993769
INFOS: >>> Indexation progress: Total nbQueuedElements = 103712979 / Total nbIndexedElements = 103492980 / Total QueueingRate = 11523 elements/sec / Loop nbQueuedElements = 28579328 / Loop nbIndexedElements = 28548183
INFOS: >>> Indexation progress: Total nbQueuedElements = 130101615 / Total nbIndexedElements = 129891151 / Total QueueingRate = 12046 elements/sec / Loop nbQueuedElements = 26388636 / Loop nbIndexedElements = 26398171
INFOS: >>> Indexation progress: Total nbQueuedElements = 157731630 / Total nbIndexedElements = 157511631 / Total QueueingRate = 12518 elements/sec / Loop nbQueuedElements = 27630015 / Loop nbIndexedElements = 27620480

Max index rate with RestHighLevelClient is 12518 elements/sec, whereas we are up to 28574 elements/sec with Transport Client.

The BulkProcessor is builded with this options:

`
.setBulkActions(20000)
.setBulkSize(new ByteSizeValue(500, ByteSizeUnit.MB))
.setFlushInterval(TimeValue.timeValueMinutes(5))
.setConcurrentRequests(6)
.setBackoffPolicy(
BackoffPolicy.exponentialBackoff(TimeValue.timeValueMillis(100), 3))
.build();

`

[elasticmachine]

Pinging @elastic/es-core-features

[jakelandis]

@xavierfacq I suspect that you maybe running into an issue we recently discovered where the BulkProcessor is overly synchronous where an ill placed sychronized is negating the ability to send concurrent requests (despite the configuration). This was addressed in #41451 but was not backported to 6.x

We typically don't recommend crossing the streams between client and server versions, but in this case I would suggest to give 7.3.0 a quick run to see if it fixes your issue. If it does, then you may want evaluate if client/server version mismatch works for your usecases (we don't test client/server across major versions).

[xavierfacq]

Hi @jakelandis , thank you for you feedback. I tried to test accross versions with Java client 7.3.0 and server 6.6.1, but there is an unsupported option, it's not a surpise :-( I am trying to disable this version but no success.

_search contains unrecognized parameter: ccs_minimize_roundtrips or GRAVE: ElasticsearchStatusException[Elasticsearch exception [type=illegal_argument_exception, reason=request [/bypath-index-alerts-201909131350] contains unrecognized parameter: [include_type_name]]]

I 'll try to find a way to test with a server having the same version, in 7.3.0

EDIT: I'll be able to run a test soon

[xavierfacq]

Hi,

Sorry but I don't have good news. I have tested the same code with version 7.3.0 and 7.3.2. I have the same problem. Indexation speed is twice faster with the good old TransportClient than with the new RestHighLevelClient, associeted to a BulkProcessor.

TransportClient this weekend:
INFO: >>> Indexation progress: Total nbQueuedElements = 25960407 / Total nbIndexedElements = 25933772 / Total QueueingRate = 14422 elements/sec / Loop nbQueuedElements = 25960404 / Loop nbIndexedElements = 25933772
INFO: >>> Indexation progress: Total nbQueuedElements = 55241671 / Total nbIndexedElements = 55227289 / Total QueueingRate = 15344 elements/sec / Loop nbQueuedElements = 29281249 / Loop nbIndexedElements = 29293517
INFO: >>> Indexation progress: Total nbQueuedElements = 88330831 / Total nbIndexedElements = 88312310 / Total QueueingRate = 16357 elements/sec / Loop nbQueuedElements = 33089152 / Loop nbIndexedElements = 33085021
INFO: >>> Indexation progress: Total nbQueuedElements = 136559799 / Total nbIndexedElements = 136542017 / Total QueueingRate = 18966 elements/sec / Loop nbQueuedElements = 48228956 / Loop nbIndexedElements = 48229707
INFO: >>> Indexation progress: Total nbQueuedElements = 174291398 / Total nbIndexedElements = 174291398 / Total QueueingRate = 19365 elements/sec / Loop nbQueuedElements = 37731595 / Loop nbIndexedElements = 37749381
INFO: ### Indexer enqueued 174291398 elements in 8415517 ms.
INFO: ### BulkProcessor awaitClose pending tasks for 77984483 ms.
INFO: ### BulkProcessors finished to treat 174291398 elements in 8416006 ms.
INFO: ### DataIndexer takes P0Y0M0DT2H37M21.624S (9441624 ms) / started at: Sun Sep 15 21:00:54 CEST 2019

RestHighLevelClient
INFOS: >>> Indexation progress: Total nbQueuedElements = 32010575 / Total nbIndexedElements = 31870576 / Total QueueingRate = 8891 elements/sec / Loop nbQueuedElements = 16754898 / Loop nbIndexedElements = 16742356
INFOS: >>> Indexation progress: Total nbQueuedElements = 51294407 / Total nbIndexedElements = 51154408 / Total QueueingRate = 9498 elements/sec / Loop nbQueuedElements = 19283832 / Loop nbIndexedElements = 19283832
INFOS: >>> Indexation progress: Total nbQueuedElements = 72258933 / Total nbIndexedElements = 72131080 / Total QueueingRate = 10035 elements/sec / Loop nbQueuedElements = 20964525 / Loop nbIndexedElements = 20976672
INFOS: >>> Indexation progress: Total nbQueuedElements = 97774337 / Total nbIndexedElements = 97654338 / Total QueueingRate = 10863 elements/sec / Loop nbQueuedElements = 25515401 / Loop nbIndexedElements = 25523258
INFOS: >>> Indexation progress: Total nbQueuedElements = 123898841 / Total nbIndexedElements = 123765292 / Total QueueingRate = 11472 elements/sec / Loop nbQueuedElements = 26124503 / Loop nbIndexedElements = 26110954
INFOS: >>> Indexation progress: Total nbQueuedElements = 148949533 / Total nbIndexedElements = 148809534 / Total QueueingRate = 11821 elements/sec / Loop nbQueuedElements = 25050689 / Loop nbIndexedElements = 25044242
INFOS: >>> Indexation progress: Total nbQueuedElements = 174292949 / Total nbIndexedElements = 174292949 / Total QueueingRate = 12103 elements/sec / Loop nbQueuedElements = 25343416 / Loop nbIndexedElements = 25483415
INFOS: ### Indexer enqueued 174292949 elements in 14247447 ms.
INFOS: ### BulkProcessor awaitClose pending tasks for 72152552 ms.
INFOS: ### BulkProcessors finished to treat 174292949 elements in 14255327 ms.
INFOS: ### DataIndexer takes P0Y0M0DT4H15M7.646S (15307646 ms) / started at: Sat Sep 14 09:03:51 CEST 2019

Hope this help :-/

[jakelandis]

@xavierfacq - I threw together a quick JMH benchmark to see if I could reproduce the 2x difference. In a not controlled environment (e.g. my laptop running quite a few things), I could not reproduce such a dramatic difference.

Here is my benchmark: https://github.com/jakelandis/index-benchmark/blob/master/src/main/java/co/elastic/JavaIndexBenchmark.java

I ran this on my 2019 macbook pro 8 core against ES 7.4 in docker on localhost in a 8G container with a 6G JVM heap. I tried to match the batching behavior between the Rest and Transport clients. I implemented a semaphore with the Transport client to limit the max number of inflight bulk requests, much like the concurrent requests of the BulkProcessor with the Rest client.

The Score is the number of documents per second.

Benchmark                                     Mode  Cnt       Score        Error  Units
JavaIndexBenchmark.indexWithRestClient       thrpt    3  155621.113 ± 130427.738  ops/s
JavaIndexBenchmark.indexWithTransportClient  thrpt    3  168650.522 ±  17595.951  ops/s

...and another run

Benchmark                                     Mode  Cnt       Score       Error  Units
JavaIndexBenchmark.indexWithRestClient       thrpt    3  154245.854 ± 86078.762  ops/s
JavaIndexBenchmark.indexWithTransportClient  thrpt    3  170530.179 ± 62364.137  ops/s

There are obviously a lot things that can influence performance here. Would you be able to take a look at the benchmark and maybe run it in your environment ? (update the hosts and with Java 12, curl -X DELETE localhost:9200/myindex;mvn clean package; java -jar target/benchmarks.jar)

[xavierfacq]

Hi, sorry for this super long response but I do not have lot of time to run a new test. I'll try to find some time to take a look at your code. Thank you for the feedback.

[xavierfacq]

As I don't have the time to investigate, I close this issue.