MQTT high delay on publish

[verybadsoldier]

I am experiencing a delay between publishing an MQTT message and the actual write to the TCP stack (similar to this issue: #547). The delays is can up to ~1 s which is pretty much a killer in out RGBWW LED firmware which can synchronize multiple LED controllers using MQTT.

It is reproducible with the sample MqttClient_Hello. This is the output of the run:

Connecting to mqtt://192.168.2.33:1883/
4936525 TCP Written: 75, Available: 75, isFinished: 1, PushCount: 1 [TcpBuf: 2705]
4947653 TCP Written: 20, Available: 20, isFinished: 1, PushCount: 1 [TcpBuf: 2760]
pm open,type:2 0
24919318 Let's publish message now. Memory free=
26015335 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
26059642 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
26064352 Message with id 2 and QoS 1 was delivered successfully.
44919329 Let's publish message now. Memory free=
(270 ms)
45190340 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
45238581 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
45242577 Message with id 3 and QoS 1 was delivered successfully.
64919318 Let's publish message now. Memory free=
(960 ms?!)
65865377 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
65919033 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
65924157 Message with id 4 and QoS 1 was delivered successfully.
84919322 Let's publish message now. Memory free=
(480 ms)
85390391 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
85444281 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
85457743 Message with id 5 and QoS 1 was delivered successfully.
104919318 Let's publish message now. Memory free=
(900 ms?!)
105815324 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
105862568 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
105866152 Message with id 6 and QoS 1 was delivered successfully.
124919325 Let's publish message now. Memory free=
(230 ms)
125140341 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
125186939 TCP Written: 55, Available: 55, isFinished: 1, PushCount: 1 [TcpBuf: 2725]
125190443 Message with id 7 and QoS 1 was delivered successfully.

Note the gap between the message Let's publish message now and the TCP written message. I added some brain-calculated time-diffs in braces.

Quoting myself from the other ticket:
Well, some time went by and I managed to at least understand a bit of what's going on. Probably nothing new to you but sending happens in MqttClient::onReadyToSendData. But that function is only called periodically so buffered data which is supposed to be sent might get delayed.
Is there anything I can do about it to make MQTT messages getting sent instantly?

I came up with a dirty hack by calling MqttClient::onReadyToSendData manually after publish. But yeah, it's dirty and I am unsure about side effects:
verybadsoldier/Sming@61c34e1

With that patch applied I get nearly instant diffs:

45758275 Let's publish message now. Memory free=
45761582 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
65758271 Let's publish message now. Memory free=
65761515 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
85758271 Let's publish message now. Memory free=
85761505 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
105758268 Let's publish message now. Memory free=
105761746 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]
125758268 Let's publish message now. Memory free=
125761775 TCP Written: 66, Available: 66, isFinished: 1, PushCount: 1 [TcpBuf: 2714]

[slaff]

But that function is only called periodically so buffered data which is supposed to be sent might get delayed.

Ok, in LWIP the timers are triggered on a period of time. In the ESP8266 LWIP version they are defined like this:

#ifndef TCP_TMR_INTERVAL
#define TCP_TMR_INTERVAL       125  /* The TCP timer interval in milliseconds. */
#endif /* TCP_TMR_INTERVAL */

#ifndef TCP_FAST_INTERVAL
#define TCP_FAST_INTERVAL      TCP_TMR_INTERVAL /* the fine grained timeout in milliseconds */
#endif /* TCP_FAST_INTERVAL */

#ifndef TCP_SLOW_INTERVAL
#define TCP_SLOW_INTERVAL      (2*TCP_TMR_INTERVAL)  /* the coarse grained timeout in milliseconds */
#endif /* TCP_SLOW_INTERVAL */

You can eventually recompile LWIP with TCP_TMR_INTERVAL value that is lower than 125. Thus resulting in frequent checks. But beware

• CPU usage will jump: if your device is running on a battery this will result in more CPU cycles and higher power consumption.
• Network retransmissions may occur: There is one thing that you should be aware when dealing with TCP - if you send packets faster than the network round-trip time this will result in (a flood of) network retransmissions. More on this in the LWIP user list.

Concerning the issue with MqttClient. We can eventually add a directive, disabled by default, that tries to poll right after queueing a publish message, similar to what you have in your work-around code. But that is a hack :( and that is why I am so hesitant to add it.

Anyone with experience in LWIP having a better idea?

[slaff]

We can eventually add a directive, disabled by default, that tries to poll right after queueing a publish message, similar to what you have in your work-around code.

Or - enable it by default but force-poll only when the message size is lower than 300 bytes. Which I guess is also the case for you @verybadsoldier, right?

[verybadsoldier]

But that function is only called periodically so buffered data which is supposed to be sent might get delayed.

Ok, in LWIP the timers are triggered on a period of time. In the ESP8266 LWIP version they are defined like this:

#ifndef TCP_TMR_INTERVAL
#define TCP_TMR_INTERVAL       125  /* The TCP timer interval in milliseconds. */
#endif /* TCP_TMR_INTERVAL */

Hm, I understand it in a way that the delay should be a maximum of 125 ms in the worst case, right? Any idea why I saw delays up to 1000 ms?
Was my test bad? I was surprised myself to see delays up to 1000 ms as in the original ticker I indeed saw delays "just" up to ~ 140 ms which would make more sense (#547 (comment)).

Concerning the issue with MqttClient. We can eventually add a directive, disabled by default, that tries to poll right after queueing a publish message, similar to what you have in your work-around code. But that is a hack :( and that is why I am so hesitant to add it.

In general I think it would make sense to be able to trigger the polling when we know there is data queued that should be sent immediately. No need to wait for polling in that case.

Yes, in my case the MQTT messages are below 300 bytes.

[verybadsoldier]

One further note:
What is particularly bad in my use case (synchronizing LED controllers via MQTT) is the jitter of the delay. A delays is basically ok (shouldn't be too high tho) when it is predictable and stable (always the same delay). It is a problem for me when it varies on every message sent. Thanks.