NEST BulkIndex performance decrease in version 2

[lonevvolf]

We have noticed a marked decrease in our indexing performance after moving from NEST 1.8.0 to NEST 2.0.4. We are using parallel calls to BulkIndexOperations, and the speed is almost halved.
Indexing 300k items with NEST 1.8.0 takes about 5.4 seconds, while with 2.0.4, it takes about 8.6 seconds. Please see the attached code samples, and let me know if were are doing something wrong, or if this is to be expected.

NESTPerformanceTest.zip

[gmarz]

@lonevvolf thanks for reporting and for attaching your perf tests. 👍 We're looking into it.

[gmarz]

Quick question though, are you testing against different versions of Elasticsearch as well? NEST 1.8 vs ES 1.x and NEST 2.0.4 vs ES 2.x?

[lonevvolf]

Both tests were against the same instance of Elastic 2.x

[lonevvolf]

Has there been any information on this item? It is stopping us from using the new version of NEST and the percolator feature it brings.

[russcam]

Hey @lonevvolf, I did some preliminary work on this just over a week ago and will update here this week. Thanks for the prompt 👍

[russcam]

Apologies for not getting back to you sooner @lonevvolf, completely unintentional!

I took your code samples and built a benchmarking harness using BenchmarkDotNet to compare NEST 1.x and 2.x versions; in fact, I've done this over several 2.x versions since your issue.

Running against a local Elasticsearch instance

NEST 1.8.2 against Elasticsearch 1.7.5

Host Process Environment Information:
BenchmarkDotNet.Core=v0.9.9.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4980HQ CPU 2.80GHz, ProcessorCount=8
Frequency=2728067 ticks, Resolution=366.5599 ns, Timer=TSC
CLR=MS.NET 4.0.30319.42000, Arch=32-bit RELEASE
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1586.0

Type=BatchTests  Mode=Throughput  LaunchCount=3  
WarmupCount=3  TargetCount=5  

Method	Total	BatchSize	Median	StdDev	Gen 0	Gen 1	Gen 2	Bytes Allocated/Op
Index	200000	50000	8.1748 s	0.1771 s	1,093.00	4,231.00	924.00	176,745,545.05

NEST 2.5.0 against Elasticsearch 2.4.1

Host Process Environment Information:
BenchmarkDotNet.Core=v0.9.9.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4980HQ CPU 2.80GHz, ProcessorCount=8
Frequency=2728067 ticks, Resolution=366.5599 ns, Timer=TSC
CLR=MS.NET 4.0.30319.42000, Arch=32-bit RELEASE
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1586.0

Type=BatchTests  Mode=Throughput  LaunchCount=3  
WarmupCount=3  TargetCount=5  

Method	Total	BatchSize	Median	StdDev	Gen 0	Gen 1	Gen 2	Bytes Allocated/Op
Index	200000	50000	10.0685 s	0.2301 s	90,933.00	30,677.00	471.00	3,821,126,097.26

NEST 2 Bleeding* (contains some slight changes to 2.5.0)

Host Process Environment Information:
BenchmarkDotNet.Core=v0.9.9.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4980HQ CPU 2.80GHz, ProcessorCount=8
Frequency=2728067 ticks, Resolution=366.5599 ns, Timer=TSC
CLR=MS.NET 4.0.30319.42000, Arch=32-bit RELEASE
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1586.0

Type=BatchTests  Mode=Throughput  LaunchCount=3  
WarmupCount=3  TargetCount=5  

Method	Total	BatchSize	Median	StdDev	Gen 0	Gen 1	Gen 2	Bytes Allocated/Op
Index	200000	50000	9.1856 s	0.1504 s	14,094.00	5,059.00	434.00	578,773,843.04

Looking at the figures here, the median time comparison between 1.x and 2 bleeding is 8.1748 s vs. 9.1856 s, respectively, or a difference of ~11%. Given that this is running against an instance of Elasticsearch and we're focused on NEST here, we ought to rule Elasticsearch out of the equation.

Running additional tests looking at bulk serialization shows similar figures

Running NEST serialization

NEST 1.9.1

BenchmarkDotNet=v0.10.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4980HQ CPU 2.80GHz, ProcessorCount=8
Frequency=2728067 Hz, Resolution=366.5599 ns, Timer=TSC
Host Runtime=Clr 4.0.30319.42000, Arch=32-bit RELEASE
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1586.0
Job Runtime(s):
	Clr 4.0.30319.42000, Arch=32-bit RELEASE

LaunchCount=3  TargetCount=5  WarmupCount=3  

Method	Total	BatchSize	Mean	StdDev	Median	Gen 0	Bytes Allocated/Op
IndexInMemory	200000	50000	1.2185 s	0.0115 s	1.2163 s	3,161.00	1,629,823,427.05

NEST Bleeding

BenchmarkDotNet=v0.10.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4980HQ CPU 2.80GHz, ProcessorCount=8
Frequency=2728067 Hz, Resolution=366.5599 ns, Timer=TSC
Host Runtime=Clr 4.0.30319.42000, Arch=32-bit RELEASE
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1586.0
Job Runtime(s):
	Clr 4.0.30319.42000, Arch=32-bit RELEASE

LaunchCount=3  TargetCount=5  WarmupCount=3  

Method	Total	BatchSize	Mean	StdDev	Median	Gen 0	Bytes Allocated/Op
IndexInMemory	200000	50000	1.3878 s	0.0070 s	1.3863 s	49,529.00	5,423,147,587.25

The difference here is ~12%.

What conclusions can be drawn from this? I think it would be prudent to not make any sweeping generalizations, but in the case of sending bulk requests of 50,000 documents with the following structure

    [ElasticsearchType(IdProperty = nameof(BiTextSegmentId), Name = "BiTextDocumentIndex")]
    internal class BiTextDocumentIndex
    {
        [String(
			Index = FieldIndexOption.No, 
			Store = true, 
			TermVector = TermVectorOption.No)]
        public Guid BiTextSegmentId { get; set; }
    }

NEST 2.x looks to be ~11-12% slower than NEST 1.x in this particular case.

One of the things that we are keen to focus on is profiling and benchmarking the client over time, so that we have much better visibility over where improvements and degradation in performance have happened. A considerable amount of effort has gone into this already in the feature/profiling branch. Once NEST 5.0.0 has GA'ed, I'm super keen to focus on this, with a view to publish our benchmarking results.

I'm going to close this issue for now, in favour of tracking benchmarking and profiling related issues on #2040.