Sockets: > 1 order magnitude slowdown when splitting message into two parts

[jakemac53]

Overview

I have some serialization code that supports various communication channels and formats. It is a relatively chatty protocol, that sends lots of fairly small messages.

When sending messages as byte data, all messages are preceded by a 32 bit int describing the length, and then that many bytes are consumed. Input bytes are handled by a MessageGrouper which produces its own stream of bytes that are just the fully formed messages.

These length bytes and message bytes are written through back to back but independent writes to the socket/stdio sink. Note that in stdio mode though these are actually grouped and we get only one list of bytes on the other end in practice (not the case for sockets, they come separately).

This performs relatively similar across all the supported channels (send ports, stdio) except for sockets, where it is significantly slower (~100x).

Note that this behaves the same in AOT or JIT modes.

Repro steps

See https://github.com/dart-lang/sdk/blob/main/pkg/_fe_analyzer_shared/benchmark/macros/serialization_benchmark.dart - you can just execute this benchmark (note the json version sometimes crashes which is a separate issue, feel free to comment out the json serialization mode from the loop at the top).

When digging into this, I discovered that by combining the length bytes and message bytes into a single call to Socket.add, the regression goes away and it is fast again.

I did that by modifying here and here to look like:

        final bytesBuilder = BytesBuilder(copy: false);
        _writeLength(result, bytesBuilder);
        bytesBuilder.add(result);
        client.add(bytesBuilder.takeBytes());

And modifying _writeLength to take a BytesBuilder.

(you also have to do similar updates to the client code which is just a big string block at the bottom and kind of a pain, but doing just half will speed it up by half).

Cpu profile

I have some cpu profiles with and without the optimization, if you ping me directly I can send them (not sure what info is contained so don't want to post them here). But the general trend is that just everything is much slower. As an example, we spend 693ms just inside the Uint8List constructor - where the optimized benchmark runs in its entirety in under 100ms.

It seems like we are possibly being cpu starved or something, I am really not sure where to begin with debugging this.

[a-siva]

/cc @brianquinlan

[jakemac53]

Note that this is showing up in real world usage of this protocol which is why I started testing it - so the benchmark is representing real behavior I am seeing. However, when I tried to create a small repro, I was not able to trigger the same behavior.

[jakemac53]

Another thing I noticed here - even after grouping the messages together, if I change the code in this example macro to be a series of awaits instead, it is about 5x faster than the current Future.wait version. I believe this is triggering some sort of similar behavior where increased chatter in a short period of time is causing an exponential slowdown.

This really makes me think this is related to the underlying Socket code in some way and not my own serialization code.

[jakemac53]

Another observation, using setOption(SocketOption.tcpNoDelay, true) also totally resolves the issue in my case (and allows me to use Future.wait again).

[jakemac53]

I believe this is simply that my use case is this use case is the absolute worst scenario for Nagles algorithm (which is what tpcNoDelay disables). We always want packets to send immediately regardless of size.

In the case where we were constantly sending new packets back to back, it kept delaying the actual sending of any of that data to have a more efficient (larger) packet.

The fact that this could actually cause a regression of 2 orders of magnitude is quite impressive though!

@brianquinlan do you think I should just close this? Should we consider disabling this option by default when connecting to localhost?

[brianquinlan]

Could you keep this open a while longer? I'm not looking at this right now but it might be that we can add some documentation somewhere to help others from getting hit by this.

[brianquinlan]

In particular, it might make sense to point out that the IOSink methods on Socket may not immediately send their data depending unless setOption(SocketOption.tcpNoDelay, true).

[mraleph]

FWIW Golang's networking stack disables Nagle's algorithm by default on TCP connections. We should probably consider if we just want to do the same.

https://github.com/golang/go/blob/0d699b6cb3e6be63846bbbee8cc7bcbfd6cb9500/src/net/tcpsock.go#L238-L239