Performance issues/expectations

[antondyad]

Hi!

We're using Spear in production and are noticing that performance might be less than ideal. We're not sure where exactly the problem resides - Spear, EventStoreDB or the network.

Our flow is as follows:

1. load events from a stream (using SpearClient.stream!)
2. build the current state from the events
3. append new events to the same stream (using SpearClient.append)

Our SpearClient module is literally as simple as this:

defmodule SpearClient do
  use Spear.Client, otp_app: :our_app
end

All this takes consistently approx 100-120 ms on production, and almost as much locally. Which seems rather slow.

• We have our app deployed on fly.io and the EventStoreDB instance on Event Store Cloud (deployed on Google Cloud in the same geographic region).
• Locally EventStoreDB runs via docker compose (in OrbStack).

When isolated to just the Spear calls (no logic of our own), we see the following on localhost:

1. SpearClient.stream!("stream_with_300_events") |> Enum.into([]) - between 40 and 60 ms
2. SpearClient.stream!("stream_with_20_events") |> Enum.into([]) - between 20 and 40 ms
3. `SpearClient.append(new_events, "stream_with_300_events", expect: last_known_revision) - around 10ms
4. `SpearClient.append(new_events, "stream_with_20_events", expect: last_known_revision) - <5ms

In production append takes typically a bit less than stream! + Enum.into([], but still hovering around 50ms in majority of cases.
As a side note, relatively simple queries to PostgresSQL (deployed on Google Cloud too) only take around 3-5 ms on average.

Would it be possible to confirm that these timings are higher than expected? Anything else we could debug or try to speed it up?

Thanks in advance for any advise!

[yordis]

How difficult would it be to test it using the C# client to have a primary baseline of ESDB itself (to some extent)?

[antondyad]

Thanks for the suggestion, @yordis!
It was an interesting experiment. Using the official C# library we're getting quite a faster stream reading on localhost:

• both longer and shorter streams are read within approx 5-10ms - quite faster than the same streams with Spear 😞

  Note: within the same dotnet run the first read is 10x slower (probably JIT and whatnot). But the consequent runs are very fast (5-10ms).

This seems to point to Spear being the bottleneck here. Any advise on how we can proceed?

[the-mikedavis]

I'm a bit busy at the moment so I haven't given this a proper look but 20-40ms does seem quite high. I'm also surprised it's cheaper to write than read.

In general I would recommend tuning the chunk_size option if you're using Spear.stream! - that is probably what is causing the stream_with_300_events to take multiple times the time as stream_with_20_events. If you read all events in one batch it should take virtually the same time for both. If your events are large though you can end up hurting performance so it's something to measure with production-like workloads and find the right value.

I took a look at a network capture of a similar Spear.stream! |> Enum.into([]) locally and I find this surprising:

https://github.com/NFIBrokerage/spear/files/12797716/spear.tgz (tar + gzipped pcapng)

We send the HTTP/2 HEADERS from the ReadReq but it looks like we're waiting for the TCP ACK from EventStoreDB to send the body of the request. Excluding the time it takes for ACKs the request should be very fast (single-digit milliseconds). So I wonder if this is something that can be fixed by tuning TCP options. I'm not quite sure what is blocking on the ACK: Mint or gen_tcp/ssl, so this needs some further debugging.

[antondyad]

We've captured the network traffic too to compare the C# implementation vs Spear. It does seem like the C# one is less chatty.
In case it's useful for further investigation, here are our three dumps:

wireshark_dumps.zip

• localhost, no ssl
• they all capture reading the same stream_with_300_events
• one is produced by the official dotnet library
• one is produced by Spear.stream!
• one is produced by Spear.read_stream (although this doesn't seem to differ that much from the stream! one).

A few other (useful?) observations from our production setup:

• even for very short streams (1-5 events) the stream! time is typically quite long (hovering around 100ms)
• the same is observable for non-existing streams
• we also have some outliers where append takes hundreds of ms

[antondyad]

Here's a bit more info from our field testing:

• we're now loading events using Spear.read_stream/3 instead of Spear.stream!/4 - this has resulted in approx 3x reduction of the average time to load 1 stream
  • this difference was not visible locally initially, but is very visible on our production setup
  • most of the "real" streams we have are rather short (ie typically only one read_stream call, with a reasonable :max_count, is necessary)
  • we also often read non-existing streams

[lessless]

@the-mikedavis, do you reckon it is possible to have similar performance characteristics between stream! and read_stream?

[the-mikedavis]

stream! and read_stream use essentially the same code path. The difference is that stream! uses Stream.unfold/2 to repeatedly read from the server so that you can eventually read even very long streams. I suspect that you see lower total latency because stream! is reading multiple times, and if individual requests have high latency then reading multiple times will have higher total latency. There is room for a small optimization in stream! to stop requesting from the server when it reads a chunk smaller than the requested chunk size. That would eliminate one extra request most of the time. I don't see that as being a true solution here though, it's just working around the high latency problems of individual reads

[lessless]

@the-mikedavis Assuming that both C# and Elixir clients are using the same endpoint (https://developers.eventstore.com/clients/grpc/reading-events.html#reading-from-a-stream) I would expect them to have the same latency.

do you think the C# client reads in a bigger batch by default?

[the-mikedavis]

I believe the C# client reads with effectively no limit and it's set rather low in Spear. You can try tuning that option but I don't think it should have an effect since individual read_stream calls are slow. I suspect this might be solved by tuning some options in gen_tcp/ssl or changing the Mint.HTTP2.stream call here to include the full request when possible. I should have some time later this week to test these ideas out

[the-mikedavis]

Sorry for the long delay! Things have been hectic lately.

I took a look at those packet captures and looking with a filter of http2.header I'm seeing similar numbers between Elixir and C# between the request and response:

Client	Req (sec)	Res (sec)	Time waiting (msec)
C#	0.015503	0.086402	70.899
Elixir	1.059172	1.093208	34.036

In the C# case the read took twice as long on the server but I see that occasionally happening locally too - it looks like the server has some sort of caching to speed up repeated reads so some take half as much time.

It's still looking to me like this latency is coming from the server and isn't really dependent on the client. Could you post a small reproduction repository or gist of the C# code you used in your test? I don't do much dotnet development so that would make it much easier for me to compare

[antondyad]

Sorry for the late reply, @the-mikedavis.
Here's the dotnet code I've used for my timings: dotnet_esdb_timing.zip

It basically does something as simple as this:

var stream_name = "Document:134";

var settings = EventStoreClientSettings.Create("esdb://localhost:2113?tls=false");
var client = new EventStoreClient(settings);

var timer = new Stopwatch(); 
timer.Start();

var result = client.ReadStreamAsync(
  Direction.Forwards,
  stream_name,
  StreamPosition.Start
);

await foreach (var @event in result) {
  Console.WriteLine(@event.Event.EventType);
}
timer.Stop();

In the attached project this is actually done twice - the first run seems to be always quite slow (cold-start?).

[the-mikedavis]

I can reproduce the timing differences. With a similar Elixir script:

Mix.install [{:spear, path: "."}, {:jason, "~> 1.0"}]

{:ok, conn} = Spear.Connection.start_link(connection_string: "esdb://localhost:2113?tls=false")

stream_name = "Document:134"

start1 = :erlang.monotonic_time()
conn
|> Spear.stream!(stream_name, from: :start, direction: :forwards)
|> Enum.each(fn event ->
  IO.puts event.type
end)
end1 = :erlang.monotonic_time()

start2 = :erlang.monotonic_time()
conn
|> Spear.stream!(stream_name, from: :start, direction: :forwards)
|> Enum.each(fn event ->
  IO.puts event.type
end)
end2 = :erlang.monotonic_time()

IO.inspect(:erlang.convert_time_unit(end1 - start1, :native, :microsecond) / 1000, label: "read no. 1")
IO.inspect(:erlang.convert_time_unit(end2 - start2, :native, :microsecond) / 1000, label: "read no. 2")

I see ~90ms for the first read with dotnet and ~2-3ms for the subsequent read. With Spear I see ~130ms for the first read and ~80ms for the second.

I'll push up the change I mentioned earlier:

There is room for a small optimization in stream! to stop requesting from the server when it reads a chunk smaller than the requested chunk size. That would eliminate one extra request most of the time.

which improves the numbers a little: 80ms for the first read and ~25ms for the second.

I took some new packet captures comparing these and the HTTP/2 requests themselves seem very fast - for both Spear and dotnet I see the network request taking not more than 2ms for the second read. So the slow-down must be somewhere in either Mint, gpb or Spear.

[the-mikedavis]

I was curious about the chatty WINDOW_UPDATE frames so I took a look into Mint. Mint sends a WINDOW_UPDATE both for the request stream (i.e. the ReadReq) and for the whole connection. That's fine and fits the spec but it sends the WINDOW_UPDATE frames eagerly any time you handle a DATA frame in Mint.HTTP2.stream/2. It can also be wasteful because you might receive a big message with a bunch of DATA frames for the same stream and then a DATA frame or the trailing HEADERs frame with the End Stream flag set. For that case I don't think there's a need to send the WINDOW_UPDATE for the stream, just the connection.

I changed Mint to collect all of the window updates in a single call of Mint.HTTP2.stream/2 (or recv) and send single frames per-stream and one for the connection level: the-mikedavis/mint@c77a13a. This didn't have any noticeable effect though, nor did commenting out the code to send WINDOW_UPDATE frames entirely. (I thought this might work since the dotnet packet capture contains no WINDOW_UPDATEs.)