High latency (~40 ms) when sending successive messages in a row - missing TCP_NODELAY

[verybadsoldier]

I am experiencing quite a high latency when sending two messages in a row (~40 ms). The client receives the first message near instantly but the second message is delayed in the broker. A single message is fine. This behavior is 100% reproducible for me.
I tried several things to figure where the delay happens. I hope I am not barking up the wrong tree here. I did the same test with emqttd and there is no delay at all.

Setup:

• Broker mosquitto 1.4.8 at 192.168.2.33 on Ubuntu 16.04.2 LTS in a VM hosted on Windows 10 on an Intel i5.
• Client 1 192.168.2.230 MQTT.fx 1.3.1 on Windows 10
• Client 2 192.168.2.36 Ubuntu using mosquitto_pub
• Client 1 subscribed to topic latency, Client 2 publishes messages to topic latency

This is how the network traffic does look in ngrep when publishing two successive messages to one topic:

T 2017/05/01 17:20:34.695801 192.168.2.36:42932 -> 192.168.2.33:1883 [AP]
  0...latency1
T 2017/05/01 17:20:34.695843 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]
  0...latency1
T 2017/05/01 17:20:34.699322 192.168.2.36:42934 -> 192.168.2.33:1883 [AP]
  0...latency2
T 2017/05/01 17:20:34.736158 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]
  0...latency2

So the message latency1 published by client 192.168.2.36 arrives at the broker at 17:20:34.695801 and is published to client 192.168.2.230 17:20:34.695843. So only 42 us later.
Then message latency2 comes in at 17:20:34.699322 but this time the broker publishes it at 17:20:34.736158 to the client. So ~35 ms later. I would expect the same low latency as for the first message.

I think that message2 is held back within the broker machine until the TCP-ACK packet for message1 is received, which is quite strange IMO.

I am reproducing this as follows:

1. On Client 2: Publish two messages in a row to one topic
   mosquitto_pub -h 192.168.2.33 -t latency -m 1; mosquitto_pub -h 192.168.2.33 -t latency -m 2
2. On the broker machine (192.168.2.33) I am using ngrep to see timestamps for incoming and outgoing messages:
   ngrep latency -q -t
3. ngrep output is (as seen above):

T 2017/05/01 17:20:34.695801 192.168.2.36:42932 -> 192.168.2.33:1883 [AP]
  0...latency1
T 2017/05/01 17:20:34.695843 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]
  0...latency1
T 2017/05/01 17:20:34.699322 192.168.2.36:42934 -> 192.168.2.33:1883 [AP]
  0...latency2
T 2017/05/01 17:20:34.736158 192.168.2.33:1883 -> 192.168.2.230:5747 [AP]
  0...latency2

---

I can see using strace with command sudo strace -p 80684 -e read,write -rthat the process mosquitto is writing the network message to the socket as soon as it read the message from the incoming socket:

strace: Process 80684 attached
     0.000000 read(11, "sendmail: all\n# /etc/hosts.allow"..., 4096) = 425
     0.000112 read(11, "", 4096)        = 0
     0.000114 read(11, "# /etc/hosts.deny: list of hosts"..., 4096) = 711
     0.000038 read(11, "", 4096)        = 0
     0.000176 read(10, "\20", 1)        = 1
     0.000039 read(10, "\"", 1)         = 1
     0.000033 read(10, "\0\6MQIsdp\3\2\0<\0\24mosqpub/10847-ubun"..., 34) = 34
     0.000074 write(3, "1493653233: Sending CONNACK to m"..., 59) = 59
     0.000059 write(10, " \2\0\0", 4)   = 4
     0.000752 read(10, "0", 1)          = 1
     0.000117 read(10, "\n", 1)         = 1
     0.000207 read(10, "\0\7latency1", 10) = 10
     0.000143 write(9, "0\n\0\7latency1", 12) = 12
     0.000199 read(10, "\340", 1)       = 1
     0.000051 read(10, "\0", 1)         = 1
     0.003352 read(11, "sendmail: all\n# /etc/hosts.allow"..., 4096) = 425
     0.000108 read(11, "", 4096)        = 0
     0.000540 read(11, "# /etc/hosts.deny: list of hosts"..., 4096) = 711
     0.000236 read(11, "", 4096)        = 0
     0.000592 read(10, "\20", 1)        = 1
     0.000157 read(10, "\"", 1)         = 1
     0.000165 read(10, "\0\6MQIsdp\3\2\0<\0\24mosqpub/10848-ubun"..., 34) = 34
     0.000080 write(10, " \2\0\0", 4)   = 4
     0.000786 read(10, "0", 1)          = 1
     0.000195 read(10, "\n", 1)         = 1
     0.000181 read(10, "\0\7latency2", 10) = 10
     0.000080 write(9, "0\n\0\7latency2", 12) = 12
     0.000445 read(10, "\340", 1)       = 1
     0.000103 read(10, "\0", 1)         = 1
     0.164655 read(8, "1", 1)           = 1
     0.000078 read(8, "&", 1)           = 1
     0.000066 read(8, "\0\35home/rgbww_a020a61624ea/clock1"..., 38) = 38

The lines in question:

     0.000207 read(10, "\0\7latency1", 10) = 10
     0.000143 write(9, "0\n\0\7latency1", 12) = 12

and

     0.000181 read(10, "\0\7latency2", 10) = 10
     0.000080 write(9, "0\n\0\7latency2", 12) = 12

Only a few microseconds between reading and writing the data which seems great.

---

But when using Wireshark to analyze whats happening on the TCP stack we can see that message1 arrives at the broker and gets published to client2 very quickly. Then message2 arrives but it is not published to client2 immediately. It only gets published right after the ACK packet from client2 for message1 arrives at the broker:

---

So is this an expected behavior with mosquitto? For me it seems like Linux TCP stack is holding the second packet back which would not be a mosquitto issue then, but as I said when I try with emqttd then everything is fine.

[verybadsoldier]

It turned out that it is far less mysterious than I thought: The delay can be fixed by activating the TCP option TCP_NODELAY which disables Nagle algorithm for the socket.

After I added this to the code the delays were gone:

setsockopt(sock, IPPROTO_TCP, TCP_NODELAY, &ss_opt, sizeof(ss_opt));

Would it maybe be an option for mosquitto to make this socket option configurable?

This is how emqttd does it:
https://github.com/emqtt/emqttd/blob/master/etc/emq.conf#L278

[ghost]

I'm also getting 40ms in simple cases where 0ms would be expected.

[ghost]

@ralight I'm collecting benchmark results from various MQTT brokers and Mosquitto performs good for large problems with many publishes but for small problems (the most common ones) I get 40ms for every case no matter how small I make it (25 subs, 1 pub takes 40ms which is the worst result I have seen for this small problem). I want to give Mosquitto a fair chance here and since it performs the best at larger problems I think this is something you should look at. If it is like @verybadsoldier says, no_delay then that should probably be fixed so that I can get accurate results and others can benefit from a faster broker.

[ralight]

I'm quite conflicted here. The operation as it is at the moment is exactly the correct behaviour. Nagle exists for a reason, we don't want to generate lots of small packets.

Disabling Nagle can give you a reduction in latency, but will likely also introduce a reduction in throughput. I personally think that throughput is more important for the broker than latency, but that is of course entirely dependent on your workload and model.

I'll see about adding the option, with appropriate guidance.

[ghost]

Well NO_DELAY exists for a reason, too. All other brokers I have tested have a 0ms latency at small broadcasts, dxcept for HiveMQ which has a 37ms delay.

[brunocodutra]

I'm facing this exact issue and totally support the suggestion of making it possible to control TCP_NODELAY.

[lategoodbye]

@ralight What kind of guidance do you think of in order to add this option?

[verybadsoldier]

Would still be awesome having an option for NO_DELAY. Anything we can do to help with?

[mschwartz]

I have mosquitto installed via package on ubuntu 17.10.

I start a tmux session and open two panes, one above the other.

In the top pane, I run "mqtt sub -h ha '#' -v
And it prints out a long list of topic/messages that have been persisted.

In the bottom pane, I run "mqtt pub -t 'test/test' -m 'test'"

The mqtt command takes about 1 second before I get a new prompt.
The message appears in the top window at roughly the same time.

In my application using mosquitto as the broker, it takes a LONG LONG time to receive a couple dozen messages on a similar number of topics. LONG LONG time is pushing a minute, or maybe 30 seconds. I didn't bother to time it.

My application is an IoT one. There are sporadic very short messages - like "light switch turned on". Topics are < 32 characters in length, messages similar.

Is the solution to find a different broker? No offense, but this ticket is 8 months old at this point.

Nagle is awful for network applications other than TTY kinds of things.

There should be an option in the config file to set TCP_NODELAY at least. Or you can use TCP_CORK and similar strategies when you know you have multiple messages queued up.

The fix seems simple enough. Parse the config for disable_nagle (or whatever you choose) and add the one line of code to setsockopt() turn it off if found in the config.

This would allow people to tune their broker for their purposes.

Thanks for the software, it is feature rich. And thanks for reading.

[karlp]

Are you sure you don't have problems from your "mqtt pub" and "mqtt sub" commands? mosquitto_pub /mosquitto_sub don't show the behaviour you're describing at all. (yes, tcp_nodelay is somethign to talk about, but your description sounds way different)

[mschwartz]

My network is gigabit ethernet. I have sub 1ms ping times between machines.

MQTT is running on a Celeron class machine, but I don't see that it should make that much of a performance penalty, latency-wise.

The mqtt command seems to be verifying/waiting for the broker to receive the message. It's not startup time for the command as far as I can see/tell.

The latency issue is quite clear in my app.

For the weather tile, there's maybe 3 MQTT messages. For the thermostat, similar. For the pool and spa tiles, about 5 each. For the TV, 5. For the fans, lights, etc, 2 each.

Devices over wifi take many seconds to receive all those messages.

[mschwartz]

Note: those messages are mostly persisted ones, not new ones sent. Some might be new, but that would be a race condition of sorts, where new state messages are sent at the same time the client is subscribing to those topics.

[ghost]

I would recommend emqtt: http://emqtt.io/ it scores very good in latency and overall throughput in my benchmarks.

[verybadsoldier]

@mschwartz
If you want to try if TCP_NODELAY fixes your problem you can use this branch:
https://github.com/verybadsoldier/mosquitto/tree/feature/tcp_nodelay

It's basically the latest official master with TCP_NODELAY applied on top.

[mschwartz]

Thanks for the tips.

If I wanted to switch to another broker, I'd look at Mosca first. I looked at emqtt, but the Erlang bits seem like a bunch of bloat I don't want. Maybe as a docker container, though!

I could add the tcp_nodelay myself. I'm quite good at C/C++. My preference is to see it done right so it propagates via package maintenance processes.

[ghost]

zZZzzZz... just do the damn benchmarking and keep those nonsense gut feeling rants to yourself @mschwartz Mosca is the slowest, by far, broker available. Jeeez!

[mschwartz]

My application is multiple micro services written for node.js. Mosca would at least be consistent with the tools I'm using.

The issue is not throughput (e.g. how many messages/second), but latency. It matters not if the code is C or interpreted Basic if there's a long delay caused by Nagle.

[ralight]

Could you try out the code in the develop branch please? You'll need to set the set_tcp_nodelay option.

[mschwartz]

Sure. I might be able to get to it this weekend.

I was considering moving the broker to a much beefier machine. That might make the persistence faster (very fast m.2 drive, fast I7 CPU, etc.), at least.

[mschwartz]

I like the code in your last commit!

[karlp]

I still maintain that with the delays you claim to be seeing, nagle wasn't the issue :) With the delays you claim to be seeing, no-one would ever have even started using mosquitto.

[verybadsoldier]

Thank you @ralight, works for me!

Same test as in the initial post:

T 2018/02/15 12:50:43.913217 192.168.2.29:41044 -> 192.168.2.33:1883 [AP]
  0...latency1

T 2018/02/15 12:50:43.913316 192.168.2.33:1883 -> 192.168.2.230:61941 [AP]
  0...latency1

T 2018/02/15 12:50:43.917240 192.168.2.29:41046 -> 192.168.2.33:1883 [AP]
  0...latency2

T 2018/02/15 12:50:43.917335 192.168.2.33:1883 -> 192.168.2.230:61941 [AP]
  0...latency2

Now I am seeing a latency between broker receiving the message from the sender and broker sending the message to the client of <100 us, nice!

Thanks!

[ghost]

I still maintain that with the delays you claim to be seeing, nagle wasn't the issue :) With the delays you claim to be seeing, no-one would ever have even started using mosquitto.

1. This is not a "claim", this is scientifically measured delays, confirmed by multiple third parties which have now been fixed.
2. A very naive assumption that no-one would use this project because of this - you clearly haven't seen the mass hysteria projects like Socket.IO have gathered despite over and over being measured to have abysmal performance problems of multiple 100ds of X worse than other projects.

[verybadsoldier]

@alexhultman
I think he was referring to @mschwartz's problem having a latency of up to 1 minute:

In my application using mosquitto as the broker, it takes a LONG LONG time to receive a couple dozen messages on a similar number of topics. LONG LONG time is pushing a minute, or maybe 30 seconds. I didn't bother to time it.

[karlp]

Indeed I was, I'm sorry if that wasn't clear.

[mschwartz]

Latency I saw was 1 second, not one minute. For one message to be sent localhost and received/printed by a 2nd process on the host. Some of that might be the mqtt command to load from "disk" and start running, but visually, the latency is ~1 second.

100 ms latency seems high to me, still. I see times of 6 ms just to fetch the HTML for my application - that's from a node.js / express..js server.

I don't think people are attracted to Socket.io for performance reasons. What's impressive is that you can get 10's of thousands of simultaneous connections on one server, with decent performance. It also transparently resorts to methods other than WebSocket to emulate WebSocket, where needed. Methods like long polling, for example.

[mschwartz]

In the browser console:

Maybe 3-4 of those lines per second were printed. This, over GigE.

I posted my issue here because at 4/sec, it does appear to be Nagle. The messages and topics are small, as you can see.

[verybadsoldier]

I really think you should test it if disabling nagle does fix it for you or not.

[mschwartz]

I plan to this weekend.

I have a day job to focus on until then.

[mschwartz]

I haven't looked at the code much, but it might be sped up by deferring the writing of persisted data to backing store in a separate thread.

[karlp]

You were writing messages to store in your js on message handler? and you're blaming nagle?

Try a demo like this: you might see nagle, but you won't be seeing anything like the order of seconds: https://gist.github.com/karlp/a2d50d0bd49313d617c9343b41caad73

[mschwartz]

I am not writing messages to store in javascript. I was talking about mosquitto. It has to write to its backing store.

[mschwartz]

@alexhultman sent me a very rude email. Unsolicited. What a classy guy.

[ghost]

Um, GitHub sent you a notification because I wrote in this thread. Now, stop tagging me @.

[mschwartz]

[ghost]

GitHub will send you (and everyone in this thread) the same mail. Everyone here got that mail already. Don't see why you are acting like such a pussy there is a reason I removed it because it wasn't adding anything to this thread even though I 100% feel that you indeed are a true moron.

[mschwartz]

And you are a child.

I am done here. You fucked things up for the guy who wrote this software.

[ghost]

Pleasure is all mine.

[mschwartz]

I stopped mosquitto, installed mosca in its place and the latency is near 0ms.

The console in dev tools prints a couple dozen lines within 1 second.

The pleasure is all mine.

Good luck @ralight.

[ghost]

You're welcome.