Akka.net: Akka.IO: Message is receiving twice slower then it is sent

[IgorFedchenko]

Details can be found in this gist, but I will give short description here.

When sending message via Akka.IO, message is going through the following path:

1. Sent from source actor to TcpConnection
2. In TcpConnection it is sent via socket and is received by another TcpConnection on other end
3. From there it is set to target actor's mailbox

I have a benchmark which makes request-response communication. In the simplest case, one actor is sending message, and then waiting while server will give response before sending next one.
And the interesting part here is that point 1 from the list above is executed twice faster then point 3. That is, delivering message from client actor to socket is twice faster then delivering message from socket to receiver. Of course I do not include the time when message is sent on the wire (point 2 in the list above).

We need to investigate this, and either understand why this is normal, or improve receiving message time.

P.S. While returning back from server to client, the delivering of the message is again twice slower from socket to client then from server to socket. So this is not related to the particular actor.

[IgorFedchenko]

Some more details.

After some more profiling, I can see that from 100% of receiving time:

• 61% of time SocketReceived message sent from socket callback to TcpConnection is getting to Receive handler
• 9% is spent on copying data to separate buffer to sent to receiver actir
• 15% is spent on performing Tell to receiving actor
• 12% is spent until receiving actor will take this message from his mailbox

Looking at this, it makes me think that we might have this 50% total overhead because of point 1. Why could it take so long to deliver this SocketReceived message to TcpConnection actor... I will try to get more details about this.

[IgorFedchenko]

All right, it is getting more interesting...
Let's look closer to the time slot from the point where message is read from socket to the moment TcpConnection actor will start working with it.
Few notable facts:

• Tell to TcpConnection actor from socket's callback takes 50-70% more time then any other Tell that is executed during message path. I.e. make Tell from your actor would take 00:00:00.0000052 (sample from one of 100K messages), and Tell from socket callback takes 00:00:00.0000083 or more. This relation is pretty stable.
• After Tell is executed, it is usually takes very little time for Receive to be called on the receiver actor side. I.e. after sending message from TcpConnection to server actor, it takes 00:00:00.0000026 to start handling it. But - not for TcpConnection to start handling that SocketReceived message, that is slow to Tell (as described above). It may take 00:00:00.0000105 for Receive to be called with this message.

All timings are taken from one of the message paths, but total summary about all messages shows same results/relations (x 100K of course)

So in general, it feels like when we are making Tell from actor, it is sent and received pretty much faster, then when we are making Tell from some different thread. Is it possible? I am not familiar with messages scheduling system yet (the process of getting message from Tell to actor's mailbox), so will try to find out the possible reason - but will appreciate any thoughts as well.

[IgorFedchenko]

To verify the last statement (in terms of Tell duration) I have added simple code to track total duration and invocation count of Tell from sender actor to TcpConnection actor, and the same for Tell from socket callback.

Results:

Named stopwatch CallbackTellStopwatch: 00:00:00.1321494 (20003 invocations)
Named stopwatch ActorTellStopwatch: 00:00:00.0258724 (10001 invocations)

So inside actor it takes ~0.026 per 10K calls, and from callback it takes ~0.066 per same 10K calls. So even slower then I thought.

But quick debugging of what Tell is doing internally does not show me, why there could be any difference... At least nothing obvious.

[IgorFedchenko]

Before getting really deep into messages scheduling, will try to rewrite receiving messages in TcpConnection actor to use child actor for it. This may also fix the problem with receive delays.

[IgorFedchenko]

You know what - actually having child actor, that is performing async reading from socket and notifies parent about results works much better then the current implementation.

Using SocketAsyncEventArgs with their callback on completion was taking ~5-5.5% of all benchmark time just to deliver SocketReceived notification to TcpConnection (Tell from callback, and until Receive will be called in TcpConnection.

But when having child actor, that is performing async reading on demand and returning results, it is only ~2.9% for the same thing (Tell from child and Receive in TcpConnection).

Which is nice. I will submit clear PR without all that profiling/debugging code, and will check if this benchmark results will be improved.

P.S. One more interesting thing is that PipeTo was working slower then child actor. It was taking 4-4.5% for the same thing - which is better then SAEA results, but not yet great.

[IgorFedchenko]

Actually, overall time is increased. Will figure out why.

[Aaronontheweb]

P.S. One more interesting thing is that PipeTo was working slower then child actor. It was taking 4-4.5% for the same thing - which is better then SAEA results, but not yet great.

Wonder if that has to do with this... https://github.com/akkadotnet/akka.net/blob/2486edf51729542eecad9bfaf70487ad443a8ade/src/core/Akka/Actor/PipeToSupport.cs#L68

[Aaronontheweb]

I wonder if including the TaskScheduler.Default might have some unintended consequences (i.e. a context switch.)

[Aaronontheweb]

Either way, probably better to keep profiling and dig deeper.

[IgorFedchenko]

I wonder if including the TaskScheduler.Default might have some unintended consequences (i.e. a context switch.)

Seems like you are right, and there is a little (very little) overhead for this. I have used plain ContinueWith without specifying the scheduler, and this gave some minimal improvement, but did not change the whole situation. I will give more details soon.

[IgorFedchenko]

All right, now I have some stable picture, but really need to think about it for some time. I will give you some details, and maybe you will have some ideas.

How I am doing profiling

The best thing I have found so far to keep track of how much time some code is taking, is using Stopwatch class. Since previous tests did not show that messages may be handled differently, I am just having few "named" stopwatches, each is started at the beginning of some section, and stopped at the end. (By section I also mean things like start before Tell in sender and stop in OnReceive in receiver).

Which sections do I track

First of all it worth to say that since in my tests there is only one client and only one server, all sections are executing sequencially, and never overlapping.

Here is what sections are tracked:

1. Between connection.Tell(Tcp.Write(message)) in client until TcpConnection.OnReceive is called with Tcp.Write message. The question here is: * how much time it takes to start handling Write from client?*
2. Right after TcpConnection.OnReceive is called and until socket.SendAsync is executed with message data. How quickly the message data is sent after TcpConnection received it. Note that this can be message from client to server, or from server to client.
3. TcpConnection is always waiting for the next data on the socket. It can be done using different ways - with SocketAsyncEventArgs, or with using async version of the method (it is done using Task<int>.Factory.FromAsync(socket.BeginReceive, socket.EndReceive) helper). So, once the message is received, I am tracking time until SocketReceived message will be delivered to TcpConnection.Receive. The question here is How quickly TcpConnection actor starts actual handling of received bytes?
4. After SocketReceived is received, tracking time until receiver actor will actually get Tcp.Received message. That is How quickly already known data is delivered to the receiver? Receiver can be either client or server.

What do I get now

As you know, I have found previously that sections 3+4 is taking twice longer then 1+2, which is weird. While making profiling, it turned out to not very sutable to switch between branches with different implementation of receiving data in TcpConnection. So I ended up with flag, that I can switch to select implementation. Implementations are:

1. SocketAsyncEventArgs usage
2. Create Child actor, and ask him to make socket.ReceiveAsync and tell as the results once ready
3. socket.ReceiveAsync with PipeTo right in TcpConnection actor
4. Modification of point 3, ReceiveAsync.ContinueWith usage without setting TaskScheduler.

And here is the report, after running on 100K messages:

Receive Mode: SocketAsyncEventArgs

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.4399332 (100000 invocations, ~00:00:00.0000043 per invocation, 1,09% of total time)
Named stopwatch 2+6. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:01.9930697 (200000 invocations, ~00:00:00.0000099 per invocation, 4,93% of total time)
Named stopwatch 3+7. FromReceiveInSocketToReceivedByTcpConnection: 00:00:03.7312153 (200002 invocations, ~00:00:00.0000186 per invocation, 9,23% of total time)
Named stopwatch 4+8. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:02.1003054 (200001 invocations, ~00:00:00.0000105 per invocation, 5,20% of total time)
Named stopwatch 5. FromServerToTcpConnection: 00:00:00.4448650 (100000 invocations, ~00:00:00.0000044 per invocation, 1,10% of total time)
Named stopwatch ReceivePath: 00:00:06.0369836 (200002 invocations, ~00:00:00.0000301 per invocation, 14,94% of total time)
Named stopwatch SendPath: 00:00:03.1731934 (200000 invocations, ~00:00:00.0000158 per invocation, 7,85% of total time)
Total time: 00:00:40.4076630

Receive Mode: ChildActor

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.7872553 (100000 invocations, ~00:00:00.0000078 per invocation, 1,64% of total time)
Named stopwatch 2+6. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:03.0898790 (200000 invocations, ~00:00:00.0000154 per invocation, 6,42% of total time)
Named stopwatch 3+7. FromReceiveInSocketToReceivedByTcpConnection: 00:00:01.5604461 (200001 invocations, ~00:00:00.0000078 per invocation, 3,24% of total time)
Named stopwatch 4+8. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:01.4483955 (200001 invocations, ~00:00:00.0000072 per invocation, 3,01% of total time)
Named stopwatch 5. FromServerToTcpConnection: 00:00:00.7778552 (100000 invocations, ~00:00:00.0000077 per invocation, 1,62% of total time)
Named stopwatch ReceivePath: 00:00:03.2449553 (200001 invocations, ~00:00:00.0000162 per invocation, 6,75% of total time)
Named stopwatch SendPath: 00:00:04.7888304 (200000 invocations, ~00:00:00.0000239 per invocation, 9,96% of total time)
Total time: 00:00:48.1042290

Receive Mode: ReceiveAsyncWithPipeTo

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.9315648 (100000 invocations, ~00:00:00.0000093 per invocation, 1,99% of total time)
Named stopwatch 2+6. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:02.5688177 (200000 invocations, ~00:00:00.0000128 per invocation, 5,50% of total time)
Named stopwatch 3+7. FromReceiveInSocketToReceivedByTcpConnection: 00:00:03.3900787 (200001 invocations, ~00:00:00.0000169 per invocation, 7,26% of total time)
Named stopwatch 4+8. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:02.2140078 (200001 invocations, ~00:00:00.0000110 per invocation, 4,74% of total time)
Named stopwatch 5. FromServerToTcpConnection: 00:00:00.9569795 (100000 invocations, ~00:00:00.0000095 per invocation, 2,05% of total time)
Named stopwatch ReceivePath: 00:00:05.7623432 (200001 invocations, ~00:00:00.0000288 per invocation, 12,34% of total time)
Named stopwatch SendPath: 00:00:04.7416540 (200000 invocations, ~00:00:00.0000237 per invocation, 10,15% of total time)
Total time: 00:00:46.6988284

Receive Mode: ReceiveAsyncWithTaskContinueWith

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.9159547 (100000 invocations, ~00:00:00.0000091 per invocation, 1,96% of total time)
Named stopwatch 2+6. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:02.6091085 (200000 invocations, ~00:00:00.0000130 per invocation, 5,57% of total time)
Named stopwatch 3+7. FromReceiveInSocketToReceivedByTcpConnection: 00:00:03.4355023 (200001 invocations, ~00:00:00.0000171 per invocation, 7,34% of total time)
Named stopwatch 4+8. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:02.1632537 (200001 invocations, ~00:00:00.0000108 per invocation, 4,62% of total time)
Named stopwatch 5. FromServerToTcpConnection: 00:00:00.9691596 (100000 invocations, ~00:00:00.0000096 per invocation, 2,07% of total time)
Named stopwatch ReceivePath: 00:00:05.7830804 (200001 invocations, ~00:00:00.0000289 per invocation, 12,36% of total time)
Named stopwatch SendPath: 00:00:04.7901952 (200000 invocations, ~00:00:00.0000239 per invocation, 10,24% of total time)
Total time: 00:00:46.8008923

Each section has indexes defining when it is executed in message path. 2+6 means that is executed after section 1, and after section 5 - that is after client's send and after server's send.

P.S. ReceivePath and SendPath are separate stopwatches, that are basically tracking the whole receiving path (sections 3+7,4+8) and sending path (sections 1,2+6,5). They are almost equal to the sum of underlying stopwatches.

Summary

Using SAEA makes ReceivePath time twice longer then SendPath - as we already know. Also, creating child actor instead to receive message from socket and send result to us works much better, message is delivered quickler. PipeTo and ContinueWith also improve receiving, but not that much.
But! For some reason, using anything instead of SAEA makes sending messages slower. Today I have made some cleanup in profiling, and ended up with pretty simple switch and clear sections tracking, but observing this behaviour constantly. Do not see any dependency of sending code with this switch - except the fact that my wrapper for socket.Receive has some drawbacks I am not aware of.

So I will get back to this with detailed profiling of sending part. Expecially FromReceiveWriteInTcpConnectionToStartSendAsync section, which actually is very strightforward but for some reason obviously depends on receiving method: it is fast for SAEA, slower for PipeTo/ContinueWith, and very slow for child actor approach. While actually does not seem to be related to this changes.

P.S. Also, I can make PR not intended to be merged, if anybody wants to see how the code looks like.

[IgorFedchenko]

One more update: I have added one more Stopwatch instance, that is starting before socket.SendAsync and finished right after await socket.ReceiveAsync line (and in OnComplete callback for SAEA case). I called this section Networking, and this is about How long it takes for a message to be transferred by socket?

Here is an updated timings:

Receive Mode: ChildActor

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.6440702 (100000 invocations, ~00:00:00.0000064 per invocation, 1,48% of total time)
Named stopwatch 2+7. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:02.9427910 (200000 invocations, ~00:00:00.0000147 per invocation, 6,77% of total time)
Named stopwatch 3. Networking: 00:00:35.4929428 (200000 invocations, ~00:00:00.0001774 per invocation, 81,59% of total time)
Named stopwatch 4+8. FromReceiveInSocketToReceivedByTcpConnection: 00:00:01.7155334 (200001 invocations, ~00:00:00.0000085 per invocation, 3,94% of total time)
Named stopwatch 5+9. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:01.4701546 (200001 invocations, ~00:00:00.0000073 per invocation, 3,38% of total time)
Named stopwatch 6. FromServerToTcpConnection: 00:00:00.6393462 (100000 invocations, ~00:00:00.0000063 per invocation, 1,47% of total time)
Named stopwatch ReceivePath: 00:00:03.4297092 (200001 invocations, ~00:00:00.0000171 per invocation, 7,88% of total time)
Named stopwatch SendPath: 00:00:04.3797479 (200000 invocations, ~00:00:00.0000218 per invocation, 10,07% of total time)
Total time: 00:00:43.4996426

Receive Mode: SocketAsyncEventArgs

Named stopwatch 1. FromClientToTcpConnection: 00:00:00.4254967 (100000 invocations, ~00:00:00.0000042 per invocation, 1,03% of total time)
Named stopwatch 2+7. FromReceiveWriteInTcpConnectionToStartSendAsync: 00:00:02.2611751 (200000 invocations, ~00:00:00.0000113 per invocation, 5,46% of total time)
Named stopwatch 3. Networking: 00:00:31.5912219 (200000 invocations, ~00:00:00.0001579 per invocation, 76,28% of total time)
Named stopwatch 4+8. FromReceiveInSocketToReceivedByTcpConnection: 00:00:03.8216419 (200002 invocations, ~00:00:00.0000191 per invocation, 9,23% of total time)
Named stopwatch 5+9. FromReceiveReadInTcpConnectionToReceivedByActor: 00:00:02.0965402 (200001 invocations, ~00:00:00.0000104 per invocation, 5,06% of total time)
Named stopwatch 6. FromServerToTcpConnection: 00:00:00.4384660 (100000 invocations, ~00:00:00.0000043 per invocation, 1,06% of total time)
Named stopwatch ReceivePath: 00:00:06.1544527 (200002 invocations, ~00:00:00.0000307 per invocation, 14,86% of total time)
Named stopwatch SendPath: 00:00:03.4086433 (200000 invocations, ~00:00:00.0000170 per invocation, 8,23% of total time)
Total time: 00:00:41.4162921

So as you can see, even since some sections are slower for child actor approach (SendPath section - do not have an idea why), the overall receive path is much faster then for SAEA, and overall message round-trip (SendPath + ReceivePath) works faster, BUT the networking is significantly slower, and this kills all the benefits.

The difference here is how receiving is implemented. For SAEA socket.ReceiveAsync(SocketAsyncEventArgs) method is used. As for child actor, there are few options:

1. socket.ReceiveAsync from SocketTaskExtensions - this is not supported by .NET Framework, but fine for experiments
2. Sync version socket.Receive - since done in child actor, and child actor is never receiving any messages until his Receive will be finished - this also works well
3. I have also tried this implementation as well:
   c# private Task<int> ReceiveAsync(Socket socket, ByteBuffer buffer) { return Task.Factory.FromAsync( socket.BeginReceive(buffer.Array, buffer.Offset, buffer.Count, SocketFlags.None, null, null), socket.EndReceive ); }
   The 1 and 2 options are faster then 3, but 2 is little bit faster (I guess due to context switching, etc). And yet - SAEA networking is faster. Well, MSDN actually says that this is the most "enhanced" version in their docs

So, the final idea is:

socket.ReceiveAsync(SocketAsyncEventArgs) is the best thing we can work with (at least without dropping current version of .NET Full Framework). Networking and allocations are optimized there very well, let's keep it.
The problem is that delivering message from that callback to TcpConnection actor for some reason is slower then it should be (~2 seconds overhead for 100K messages and ~41 sec of total execution time - 5% overhead, compare to same message delivery from child actor, see timings above).
Anything other then this ReceiveAsync is slow. So we have to fix this message scheduling issue, and get this fastest socket API working well with actors.

So, have to profile some Akka internals.

[Aaronontheweb]

The extra event handler hop from SAEA —> socket actor includes a context switch and an actor mailbox invocation. That might explain the latency after the event is raised.

[IgorFedchenko]

The extra event handler hop from SAEA —> socket actor includes a context switch and an actor mailbox invocation. That might explain the latency after the event is raised.

Do you think this delay can be normal then? Well, even if it is, maybe we should try to find another way to pass data between thread context's then. Maybe pass some synchronization primitive to that callback, and create child actor that will wait for this primitive to trigger (i.e. ManualResetEvent) and send notification to socket actor once trigger occurs. Need to check, maybe this will work faster then sending message to other context via actors' dispatching system.

[IgorFedchenko]

Just to summarize here.

I have made few more experiments with thread synchronization, i.e. tried to use ManualResetEventSlim as a SAEA UserToken - that is, ask child actor to wait for manual event, and set this event in SAEA callback (so instead of passing message to TcpConnection from callback, I am asking child actor to do that) - still does not give better results, because there is 0.2s between ev.Set() in callback and ev.Wait() returns in child actor (for 10K messages) added to time of message passing from child to TcpConnection .

My conclusion: receiving messages in ping-pong is ~twice slower then sending them because we have a context switch that takes time. Any option that allows to avoid context switching (i.e. receiving in child actor without SAEA usage) is faster in message passing but too much slower in sockets handling.
So, you either have context switch, either worse sockets handling. Context switch generally takes less time, so the current implementation is faster then anything I was trying.

_Of course, using multiple messages sent in batch and connection multiplexing would improve throughput, so "twice slower" here is not related to the general case. Only in current context._

Also, does not seem that some optimization of message scheduling will give any results since using other ways of threads communication (including ManualResetEventSlim and TaskCompletionSource) do not give better results.

@Aaronontheweb Unfortunately seems like there is nothing to improve in terms of this issue. Just another well researched part of Akka.IO in terms of optimization.

I am closing it for now, but if someone has any suggestions - you are welcome to share and reopen issue.

[Aaronontheweb]

Thanks for your thorough research here - we're probably better off making improvements on the dispatching side then in order to try to improve throughput and performance in Akka.IO, at least over a localhost connection.

We need to add some benchmarking infrastructure to test things over a real, live connection at some point so the I/O factor can show up more easily - but I'm undecided on how best to do that. Cloud-hosted Kubernetes environment with multiple nodes (host machines) is probably a reasonably good real-world substitute.