Performance hit in NEST 6.x

[kaaresylow]

NEST/Elasticsearch.Net version:
5.6.2
6.1.0

Elasticsearch version:
5.5.1
6.2.3

Description of the problem including expected versus actual behavior:
In the process of upgrading our Elasticsearch setup from version 5.x to 6.x we have noticed a performance impact that translates into slower response time in our service that uses Elasticsearch as data storage. The slower response is mostly visible when dealing with large documents with complex structures e.g. geojson.

The two Elasticsearch clusters performs equally when we are testing them directly via Apache ab so I guess the performance hit is related to the NEST library.

I have done some performance testing using BenchmarkDotNet (on a simplified implementation described further down) where NEST v. 6 has a noticeable higher response compared to v. 5.
I hope you can shed some light on why we are seeing this behaviour.
Thanks

Method	Mean	StdDev
NEST 5	73.11 ms	2.558 ms
NEST 6	92.15 ms	3.054 ms

Steps to reproduce:

1. Add an index to Elasticsearch with this mapping

{
  "properties": {
    "boundaries": {
      "properties": {
        "boundary": {
          "type": "geo_shape"
        },
        "type": {
          "type": "text",
          "index": false
        }
      }
    }
  }
}

2. Insert document https://gist.github.com/kaaresylow/ece0d2dd88175653fb4fa44710297d14

var connectionPool = new SingleNodeConnectionPool(new Uri("url"));
var settings = new ConnectionSettings(connectionPool).EnableHttpCompression();
var client = new ElasticClient(settings);

var response = client.Get<Document>(1, idx => idx
    .Index("documents")
    .Type("documentmodel"));

public class Document
    {
        public IEnumerable<PlaceBoundary> Boundaries { get; set; }
    }

    public class PlaceBoundary
    {
        public string Type { get; set; }

        public GeoJsonBoundary Boundary { get; set; }
    }

    public class GeoJsonBoundary
    {
        public string Type { get; set; }

        public object Coordinates { get; set; }

        public object Bbox { get; set; }

        public object Crs { get; set; }
    }

[russcam]

Thanks for opening @kaaresylow. I'm keen to dive into this but I'm unlikely to get around to it until next week.

[russcam]

@kaaresylow I've put together a benchmark of NEST 5.6.2 against 6.1.0, using an InMemoryConnection that returns the response JSON that you posted in the gist. I've rewritten the NEST assemblies and their immediate dependencies to allow them both to be referenced in the same project.

The test is pretty simple

using System;
using System.Collections.Generic;
using System.IO;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Configs;
using BenchmarkDotNet.Diagnosers;
using BenchmarkDotNet.Environments;
using BenchmarkDotNet.Horology;
using BenchmarkDotNet.Jobs;
using Elasticsearch.Net562;

namespace NestVersionBenchmark.Benchmarks
{
    [Config(typeof(Config))]
    public class GithubIssue3236
    {
        private class Config : ManualConfig
        {
            public Config()
            {
                Add(
                    Job.Default
                        .With(Platform.AnyCpu)
                        .With(Jit.Default));
                
                Add(
                    Job.Default
                        .With(Platform.AnyCpu)
                        .With(Jit.RyuJit));
                
                Add(MemoryDiagnoser.Default);
            }
        }
        
        private readonly Nest562.ElasticClient _client562;
        private readonly Nest610.ElasticClient _client610;
        
        public GithubIssue3236()
        {
            var bytes = GetResponseBytes();
            var settings562 = new Nest562.ConnectionSettings(new SingleNodeConnectionPool(new Uri("http://localhost:9200")), new InMemoryConnection(bytes));          
            _client562 = new Nest562.ElasticClient(settings562);
            
            var settings610 = new Nest610.ConnectionSettings(new Elasticsearch.Net610.SingleNodeConnectionPool(new Uri("http://localhost:9200")), new Elasticsearch.Net610.InMemoryConnection(bytes));  
            _client610 = new Nest610.ElasticClient(settings610);
        }

        [Benchmark]
        public Nest562.IGetResponse<Document> Get562()
        {
            return _client562.Get<Document>(1, idx => idx
                .Index("documents")
                .Type("documentmodel"));
        }

        [Benchmark]
        public Nest610.IGetResponse<Document> Get610()
        {
            return _client610.Get<Document>(1, idx => idx
                .Index("documents")
                .Type("documentmodel"));
        }
        
        public class Document
        {
            public IEnumerable<PlaceBoundary> Boundaries { get; set; }
        }

        public class PlaceBoundary
        {
            public string Type { get; set; }

            public GeoJsonBoundary Boundary { get; set; }
        }

        public class GeoJsonBoundary
        {
            public string Type { get; set; }

            public object Coordinates { get; set; }

            public object Bbox { get; set; }

            public object Crs { get; set; }
        }
        
        private static byte[] GetResponseBytes()
        {
            using (var stream = typeof(GithubIssue3236).Assembly.GetManifestResourceStream("NestVersionBenchmark.Benchmarks.GithubIssue3236.json"))
            using (var memoryStream = new MemoryStream())
            {
                stream.CopyTo(memoryStream);
                return memoryStream.ToArray();
            }
        }
    }
}

On the machine I'm currently on, the results are

BenchmarkDotNet=v0.10.14.585-nightly, OS=Windows 10.0.16299.371 (1709/FallCreatorsUpdate/Redstone3)
Intel Core i7-2920XM CPU 2.50GHz (Sandy Bridge), 1 CPU, 8 logical and 4 physical cores
Frequency=2433513 Hz, Resolution=410.9286 ns, Timer=TSC
  [Host]     : .NET Framework 4.7.1 (CLR 4.0.30319.42000), 32bit LegacyJIT-v4.7.2633.0
  Job-HASSSB : .NET Framework 4.7.1 (CLR 4.0.30319.42000), 64bit LegacyJIT/clrjit-v4.7.2633.0;compatjit-v4.7.2633.0
  Job-IYUISG : .NET Framework 4.7.1 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.2633.0

Platform=AnyCpu  

Method	Jit	Mean	Error	StdDev	Gen 0	Allocated
Get562	Default	6.109 ms	0.0228 ms	0.0190 ms	187.5000	774.58 KB
Get610	Default	6.109 ms	0.0399 ms	0.0374 ms	187.5000	773.83 KB
Get562	RyuJit	5.992 ms	0.0330 ms	0.0292 ms	187.5000	774.58 KB
Get610	RyuJit	6.014 ms	0.0396 ms	0.0370 ms	187.5000	773.83 KB

5.6.2 and 6.1.0 benchmarks look very similar.

Would you be able to share further information about

1. Runtime e.g. .NET Framework, .NET Core, and version
2. Application TFM e.g. net46, netcoreapp2.0

[kaaresylow]

@russcam thanks for looking into this.
I agree your results looks very similar. I have tried replicating your test using an InMemoryConnection and I still get significant different results. I have performed the test on both net462 and netcoreapp2.0 with the same outcome.

BenchmarkDotNet=v0.10.14, OS=Windows 10.0.16299.309 (1709/FallCreatorsUpdate/Redstone3)
Intel Core i5-4590 CPU 3.30GHz (Haswell), 1 CPU, 4 logical and 4 physical cores
Frequency=3215221 Hz, Resolution=311.0206 ns, Timer=TSC
.NET Core SDK=2.1.4
  [Host]     : .NET Core 2.0.5 (CoreCLR 4.6.26020.03, CoreFX 4.6.26018.01), 64bit RyuJIT
  Job-ZMNRCM : .NET Core 2.0.5 (CoreCLR 4.6.26020.03, CoreFX 4.6.26018.01), 64bit RyuJIT

Jit=RyuJit  Platform=AnyCpu

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
Get562	15.51 ms	0.0579 ms	0.0542 ms	531.2500	265.6250	-	3.2 MB
Get610	38.46 ms	0.2187 ms	0.2046 ms	1500.0000	687.5000	312.5000	8.39 MB

The only difference between the two tests are the version of the NEST library
<PackageReference Include="NEST" Version="5.6.2" /> vs <PackageReference Include="NEST" Version="6.1.0" />
Can I provide you with more information?
Thanks again.

[russcam]

Have a chance to look at this again now @kaaresylow. Would you be able to re-run your benchmarks with NEST 6.2.0? There were several performance improvements made that show it to be faster than 5.x.

[fritsduus]

We recently upgraded to 6.3.1 from 2.x and took a significant performance hit on the clients. I have been profiling our system and my findings might be relevant to the issue above.
My initial findings points to the ReadJson method in the Nest.SourceConverter class:

public override object ReadJson(JsonReader reader, Type objectType, object existingValue, JsonSerializer serializer)
{
	var token = reader.ReadTokenWithDateParseHandlingNone();
	using (var ms = token.ToStream(serializer.GetConnectionSettings().MemoryStreamFactory))
		return sourceSerializer.Deserialize(objectType, ms);
}

Here is the part of the call tree from my profiling that covers the ReadJson method:

Function Name	Inclusive Samples
Nest.SourceConverter.ReadJson	37.290
-> Nest.JsonNetSerializer.ConnectionSettingsAwareSerializerBase.Deserialize	18.616
-> Nest.Json.Linq.JToken.ReadFrom	14.061
-> Nest.JTokenExtensions.ToStream	4.421
-> Elasticsearch.Net.RecyclableMemoryStream.ctor	121
-> ....	...

As I understand it, the Deserialize method does the real work, the remaining three are all about creating the stream to be parsed into Deserialize. When creating the stream the JSON is parsed and it is parsed again in the Deserialize method, so the JSON is actually parsed twice. If there was a way to parse the JsonReader directly into the Deserialize method we can cut it down to one parse and cut the cost of the ReadJson method by approx. 50%.

I have made an experiment in a fork of NEST that confirms this. To do the experiment I added a new interface to NEST and extended the ReadJson method like this:

namespace Nest {
	public interface IDeserializeFromJsonReader {
		object Deserialize(JsonReader reader, Type objectType);
	}
}

public override object ReadJson(JsonReader reader, Type objectType, object existingValue, JsonSerializer serializer)
{
	var sourceSerializer = serializer.GetConnectionSettings().SourceSerializer;
	if (sourceSerializer is IDeserializeFromJsonReader fromJsonReaderSerializer)
		return fromJsonReaderSerializer.Deserialize(reader, objectType);

	var token = reader.ReadTokenWithDateParseHandlingNone();
	using (var ms = token.ToStream(serializer.GetConnectionSettings().MemoryStreamFactory))
		return sourceSerializer.Deserialize(objectType, ms);
}

I then implemented the IDeserializeFromJsonReader interface in my SourceSerializer and ran a new profiling session. The ReadJson method then looked like this in the call tree:

Function Name	Inclusive Samples
Nest.SourceConverter.ReadJson	21.608
-> Nest.JsonNetSerializer.MySerializerThatDeserializesFromJsonReader.Deserialize	21.595
-> Nest.JsonExtensions.GetConnectionSettings	7
-> ...	...
(The profiled workload is not exactly the same as before so you can't compare the absolute numbers).

From a performance point of view there is a lot to win by adding an interface like IDeserializeFromJsonReader, but I'm unsure if it will cause other problems... I'm happy to create a PR with the above changes plus an implementation in the InternalSerializer, if you're interested.
/ Frits

[russcam]

@fritsduus Thank you for the detailed information.

There is a cost associated with using JsonNetSerializer at present, as there isn't a clean way to pass a Stream to JsonNetSerializer, to only deserialize objects that you control e.g. documents returned in _source fields. Can you see a clean way to pass the Stream? If so, we'd love to improve how this works! Note that the cost isn't paid when using the built-in serializer as the SourceSerializer.

One of the reasons for internalizing Json.NET in the client is so that it can be replaced with a faster serializer implementation going forward. As such, we wouldn't want to introduce APIs that expose Json.NET specific implementation details such as a IDeserializeFromJsonReader method.

We expect to start on the serializer work shortly, and have been looking at SpanJson and Utf8Json as potential candidates.

[fritsduus]

@russcam Thank you for your response.

I think your long term goal of replacing Json.NET with a faster serializer is very good. I was also looking at creating a SourceSerializer using Jil or Utf8Json, but then I realized the internal cost of the SourceConverter which couldn't really be removed by such a solution.

I don't see a simple way to pass the Stream at the moment. It looks like a larger task to replace the serializer. I was aiming for a quick win with the suggested solution as we are in need of a solution to our problem before Black Friday.

[DSilence]

We're using Utf8Json as a serializer/deserializer for NEST client right now with great success (in our case, we saw up to 10 times improved performance in deserialization for our workload).

[Mpdreamz]

Just a quick heads up that we expect to switch to Utf8Json as the default internal serializer with 7.0.

One nice thing that @russcam found is that the hand off of the stream to the user defined serializer is now much much faster.

[florin-nedelcu]

@DSilence can you please provide an example of how you had used Utf8Json as a serializer/deserializer for NEST?

[DSilence]

@florin-nedelcu In our case, only a couple of heavy search requests required a more performant deserialization, so for them I've used a low level client.

var searchResult = await _elasticClient.LowLevel.SearchAsync<BytesResponse>(indexName, PostData.Serializable(searchDescriptor));
var result = Utf8Json.JsonSerializer.Deserialize<ElasticPointResponse>(searchResult.Body);

If there is a need for full replacement I suggest referring to https://www.elastic.co/guide/en/elasticsearch/client/net-api/master/custom-serialization.html. Keep in mind that some internal types will require customized formatters for UTF8JSON (e.g. geography).

[SidHuntt]

@Mpdreamz when is 7.0 planned for release?
We have a similar perf problem with 6.x serializer.
Ty!