From time to time delays due to TCP retransmissions

[Bascht74]

Hello,

I have now transferred almost all devices to Tasmota and am very happy with the functionality and possibilities Tasmota offers. Really great what you can do with it.

I have not yet converted the Shelly dimmer devices. here I do not dare because of the "ripple control signal" in Germany and the alternative firmware needed.

However, this state (both Tasmota & Shelly firmware) is quite interesting to look at the network page.
Note: The Tasmota devices are mostly installed directly next to the Shelly devices and have a good reception.

On the network side, I use UniFi (Nano-HD and In-wall-HD devices) with current firmware 5.43.19.12493
(according to the changelog: [UAP-MTK] Improve WiFi compatibility with IoT devices.)

Note: The Shellys had had many problems with WiFi in the past, with crashes every now and then where the device had to be restarted. In the current firmware 1.93RC4, these seem to be eliminated. UniFi shows me 100% Experiance here.

This is not the case with the Tasmota devices: According to Wireshark, there seems to be tcp retransmissions from the Tasmota device from time to time.

In practice, this is noticeable with delays when you press a button and it controls another device. Here you have to wait sporadically 1-2 seconds ... and you possibly press again, which then switches the device off again, after both a executed :-)

It is interesting that the Tasmota device always receives responses from the server (e.G. MQTT) promptly, but sometimes responds itself with a delay of over one second. Then TCP retransmission is engaged.

When you do a ping, you always see long response times at the beginning, which then suddenly drop to a few milliseconds and stay there if you go on.
Until the device then has to do nothing again, about 30-60 seconds pass and then you ping again. Than it happens again.

The same is with HTTP requests: The first one sometimes takes longer (1-2 seconds), then it slips and stays that way until you do nothing again for 30-60 seconds.

I have already tried to systematically change the various parameters that Tasmota offers (setoption57, setoption56, setoption41, Sleep, SetOption60, Reset 3), but nothing has brought a change. And I don't see anything at the Console.

Since I am currently running out of ideas, maybe someone has other thought/directions to look at:
Are there any other parameters in Tasmota that can be tried?
Is there anyone who has also observed such problems with Tasmota 9.2.0 / Unifi 5.43.19.12493?
Is there a recommended older Tasmota version that uses an older state of the ESP8266 SDK that I could try out to see, weather the behavior changes?

Is there a plan to move to the 3.X SDK versions?
Here I see on GitHub a lot of WIFI fixes and also support for current features like 11kv roaming support, that is enabled in more and more devices (espressif/ESP8266_RTOS_SDK@6cf4b3d).
Maybe that is what the Shelly guys did?

What I'm still going to try myself:
I'm going to put in an older UniFi version and see, if it changes anything.

Greetings and thanks for any hint,

Sebastian

[arendst]

Regarding HTTP GUI requests you might be surprised to find that Firefox responds a lot quicker than Chrome.

[Bascht74]

Thanks for the Tipp, and merry chrismas!

Because of that I tried it out with Curl on a command line and watched the requests with wireshark directly from the accesspoint (in the Nighttime when there is no streaming going on from the kids :-)

It is always the same pattern: first you get some retransmissions and after that it run warm an no retransmission anymore. If you stop the http requests/mqtt messages/ping or whatever for some time and start the same request again there is again these retransmissions for the first 1-4 packets sent because the device is not answering in time, never the other way around...

Sebastian

[s-hadinger]

Hi Sebastian,

I've seen similar behavior for a while but didn't took time to check with wireshark. I first suspected ARP but as you showed it, it's something different that creates TCP retransmits.

I confirm that Chrome generates some HTTP traffic that Tasmota/Arduino doesn't like. I'm not sure if why, but using Chrome sometimes causes slow downs of Tasmota and a decrease of ~5Kb of available heap memory, that is recovered a few minutes later. Firefox does not generate this behavior.

I have a UniFi nano-HD like you, but I had similar issues with my previous AP. So I'm not sure it's Unifi-specific.

After a reboot of Tasmota, performance is great again. Then degrades after hours/days.

If you find how to solve this, I would be immensely grateful.

[ascillato]

I confirm that Chrome generates some HTTP traffic that Tasmota/Arduino doesn't like. I'm not sure if why, but using Chrome sometimes causes slow downs of Tasmota and a decrease of ~5Kb of available heap memory, that is recovered a few minutes later. Firefox does not generate this behavior.

The difference between Firefox and Chrome is that google didn't implement the full version of HTTP2 for unencrypted http. So, as all the devices in your home, like your router, etc uses http instead of https (that requires an url and a certificate), chrome is slow. If you try firefox or safari, you don't see this problem. Is not related to Tasmota. You can check also this if you make a webserver under http in an Raspberry pi.

[Bascht74]

Here is an example:

The "tamotized" shelly device did'nt answer at 11:33:43,775183 so that a retransmission was sent at 11:44.424506 (650 ms later) and after that the device answered at 11:33:44.924866 (500ms after the retransmission and 1.150 s after the first request. After that the chatting between the two devices was going fast as supposed to be. Same thing observed with ping, mqtt messages...

Tasmota TCP retransmission.zip

It looks that way in Unifi:

somehow strange.
Went back to previous firmware 4.3.21.11325 at 19:00. Let's see if it changes something.

Devices with shelly firmware look like that (1.93RC4):

[s-hadinger]

Did you observe ARP traffic during this period? Or whatever equivalent of ARP for Wifi?

[Bascht74]

I did now, nothing spectacular:

One time a second delay...
There was in my opinion no reason for that delay:

[Jason2866]

Your question about using RTOS the answer is no. Tasmota is build using Arduino ESP8266.
Arduino ESP8266 is based on nonos-sdk. There is no ArduinoESP8266 version planned for RTOS

[Bascht74]

Your question about using RTOS the answer is no. Tasmota is build using Arduino ESP8266.
Arduino ESP8266 is based on nonos-sdk. There is no ArduinoESP8266 version planned for RTOS

@Jason2866 Thanks for pointing that out. I found out myself when I dug deeper into the matter. So I have to re-question:
Is there a plan to move to the 3.X NONOS SDK versions? (https://github.com/espressif/ESP8266_NONOS_SDK)
I saw that NodeMCU did that a couple of months ago.
Maybe I will try their firmware on one device to see weather that changes something to my wifi problems.

Firmware 4.3.21.11325 brought nothing special for tasmotized devices, only shelly devices got worse, so I went back to 5.43.19.12493.
And I changed the DTIM from 3 to 1. But that doesn't help.

Here is a Ping directly from the AP (NanoHD) of a Tasmota device. As you all can see, the first responses is quite long, but after four pings it goes down to low ms.

Wohnzimmer-BZ.5.43.19# ping 192.168.175.40
PING 192.168.175.40 (192.168.175.40): 56 data bytes
64 bytes from 192.168.175.40: seq=0 ttl=255 time=402.058 ms
64 bytes from 192.168.175.40: seq=1 ttl=255 time=829.732 ms
64 bytes from 192.168.175.40: seq=2 ttl=255 time=140.105 ms
64 bytes from 192.168.175.40: seq=3 ttl=255 time=41.633 ms
64 bytes from 192.168.175.40: seq=4 ttl=255 time=8.739 ms
64 bytes from 192.168.175.40: seq=5 ttl=255 time=3.618 ms
64 bytes from 192.168.175.40: seq=6 ttl=255 time=17.161 ms
64 bytes from 192.168.175.40: seq=7 ttl=255 time=46.927 ms
64 bytes from 192.168.175.40: seq=8 ttl=255 time=5.956 ms
64 bytes from 192.168.175.40: seq=9 ttl=255 time=3.706 ms
64 bytes from 192.168.175.40: seq=10 ttl=255 time=3.274 ms
64 bytes from 192.168.175.40: seq=11 ttl=255 time=4.926 ms
64 bytes from 192.168.175.40: seq=12 ttl=255 time=1.781 ms
64 bytes from 192.168.175.40: seq=13 ttl=255 time=5.365 ms

I found something here: https://blog.creations.de/?p=149
I will try to keep one device awake with while true ; do ping -c1 192.168.175.40 ; sleep 5 ; done executed on the AP.
Notes: An hour past and so far the UI keeps responsive and no retransmissions.
Is there a way to do the same with the mqtt pings (keep alive) from the client side?
Or a rule that sends out a static mqtt publish message? (Just to see a change of the behaiviour)

I've seen similar behavior for a while but didn't took time to check with wireshark. I first suspected ARP but as you showed it, it's something different that creates TCP retransmits.
@s-hadinger Yes, I think that, too.

I confirm that Chrome generates some HTTP traffic that Tasmota/Arduino doesn't like. I'm not sure if why, but using Chrome sometimes causes slow downs of Tasmota and a decrease of ~5Kb of available heap memory, that is recovered a few minutes later. Firefox does not generate this behavior.
@s-hadinger I didn't try, but for my tests I use CURL.

After a reboot of Tasmota, performance is great again. Then degrades after hours/days.
@s-hadinger Yes. But if I constantly ping the device every 5 seconds even chrome is very responsive so far (even that the device needs to process the pings).
Maybe you can try that and confirm:

1. Restart a device and
2. Ping the device via while true ; do ping -c1 192.168.175.40 ; sleep 5 ; done from the AP.
3. Wait some hours if it does degrade again.

Sometimes the pings of the device are almost always high (round-trip min/avg/max = 2.478/88.086/866.872 ms).
I also read something of a "misalignment" that could happen for the wifi driver if it goes to (deeper) sleep modes (waking up to late so that the AP already sent the data, but the device didn't received it).

But I don't find the web page with that observation right now.
EDIT: It found it: esp8266/Arduino#6886 (comment)
clould it be that the same problem could affect other transmissions (ping/mqtt/etc.) as well?

Here you see my problem:

Wohnzimmer-BZ.5.43.19# ping 192.168.175.40 -W 5
PING 192.168.175.40 (192.168.175.40): 56 data bytes
64 bytes from 192.168.175.40: seq=0 ttl=255 time=3.743 ms
64 bytes from 192.168.175.40: seq=1 ttl=255 time=40.580 ms
64 bytes from 192.168.175.40: seq=2 ttl=255 time=2.667 ms
64 bytes from 192.168.175.40: seq=3 ttl=255 time=3.517 ms
64 bytes from 192.168.175.40: seq=4 ttl=255 time=94.748 ms
64 bytes from 192.168.175.40: seq=5 ttl=255 time=4.418 ms
64 bytes from 192.168.175.40: seq=6 ttl=255 time=19.866 ms
64 bytes from 192.168.175.40: seq=7 ttl=255 time=42.625 ms
64 bytes from 192.168.175.40: seq=8 ttl=255 time=267.525 ms
64 bytes from 192.168.175.40: seq=9 ttl=255 time=8.768 ms
64 bytes from 192.168.175.40: seq=10 ttl=255 time=3.570 ms
64 bytes from 192.168.175.40: seq=11 ttl=255 time=5.010 ms
64 bytes from 192.168.175.40: seq=12 ttl=255 time=3.401 ms
64 bytes from 192.168.175.40: seq=13 ttl=255 time=3.997 ms
64 bytes from 192.168.175.40: seq=14 ttl=255 time=169.504 ms
64 bytes from 192.168.175.40: seq=15 ttl=255 time=85.092 ms
64 bytes from 192.168.175.40: seq=16 ttl=255 time=422.627 ms
64 bytes from 192.168.175.40: seq=17 ttl=255 time=3.715 ms
64 bytes from 192.168.175.40: seq=18 ttl=255 time=3.194 ms
64 bytes from 192.168.175.40: seq=19 ttl=255 time=276.892 ms
64 bytes from 192.168.175.40: seq=20 ttl=255 time=586.989 ms
64 bytes from 192.168.175.40: seq=21 ttl=255 time=18.646 ms
64 bytes from 192.168.175.40: seq=22 ttl=255 time=3.426 ms
64 bytes from 192.168.175.40: seq=23 ttl=255 time=23.393 ms
64 bytes from 192.168.175.40: seq=24 ttl=255 time=6.582 ms
64 bytes from 192.168.175.40: seq=25 ttl=255 time=6.197 ms
64 bytes from 192.168.175.40: seq=26 ttl=255 time=5.222 ms
64 bytes from 192.168.175.40: seq=27 ttl=255 time=2.478 ms
64 bytes from 192.168.175.40: seq=28 ttl=255 time=3.467 ms
64 bytes from 192.168.175.40: seq=29 ttl=255 time=13.438 ms
64 bytes from 192.168.175.40: seq=30 ttl=255 time=48.120 ms
64 bytes from 192.168.175.40: seq=31 ttl=255 time=65.823 ms
64 bytes from 192.168.175.40: seq=32 ttl=255 time=82.105 ms
64 bytes from 192.168.175.40: seq=33 ttl=255 time=3.953 ms
64 bytes from 192.168.175.40: seq=34 ttl=255 time=6.604 ms
64 bytes from 192.168.175.40: seq=35 ttl=255 time=8.677 ms
64 bytes from 192.168.175.40: seq=36 ttl=255 time=3.390 ms
64 bytes from 192.168.175.40: seq=37 ttl=255 time=19.861 ms
64 bytes from 192.168.175.40: seq=38 ttl=255 time=194.320 ms
64 bytes from 192.168.175.40: seq=39 ttl=255 time=3.933 ms
64 bytes from 192.168.175.40: seq=40 ttl=255 time=3.191 ms
64 bytes from 192.168.175.40: seq=41 ttl=255 time=148.459 ms
64 bytes from 192.168.175.40: seq=42 ttl=255 time=170.707 ms
64 bytes from 192.168.175.40: seq=43 ttl=255 time=104.915 ms
64 bytes from 192.168.175.40: seq=44 ttl=255 time=217.871 ms
64 bytes from 192.168.175.40: seq=45 ttl=255 time=4.291 ms
64 bytes from 192.168.175.40: seq=46 ttl=255 time=643.389 ms
64 bytes from 192.168.175.40: seq=47 ttl=255 time=866.872 ms
64 bytes from 192.168.175.40: seq=48 ttl=255 time=3.935 ms
64 bytes from 192.168.175.40: seq=49 ttl=255 time=4.584 ms
64 bytes from 192.168.175.40: seq=50 ttl=255 time=206.556 ms
64 bytes from 192.168.175.40: seq=51 ttl=255 time=36.367 ms
64 bytes from 192.168.175.40: seq=52 ttl=255 time=134.770 ms
64 bytes from 192.168.175.40: seq=53 ttl=255 time=50.197 ms
64 bytes from 192.168.175.40: seq=54 ttl=255 time=48.475 ms
64 bytes from 192.168.175.40: seq=55 ttl=255 time=3.618 ms
64 bytes from 192.168.175.40: seq=56 ttl=255 time=3.073 ms
64 bytes from 192.168.175.40: seq=57 ttl=255 time=3.817 ms
64 bytes from 192.168.175.40: seq=58 ttl=255 time=39.796 ms
64 bytes from 192.168.175.40: seq=59 ttl=255 time=18.203 ms
^C
--- 192.168.175.40 ping statistics ---
60 packets transmitted, 60 packets received, 0% packet loss
round-trip min/avg/max = 2.478/88.086/866.872 ms

If you restart the device it does down again:

Wohnzimmer-BZ.5.43.19# ping 192.168.175.40
PING 192.168.175.40 (192.168.175.40): 56 data bytes
64 bytes from 192.168.175.40: seq=0 ttl=255 time=3.532 ms
64 bytes from 192.168.175.40: seq=1 ttl=255 time=4.026 ms
64 bytes from 192.168.175.40: seq=2 ttl=255 time=4.000 ms
64 bytes from 192.168.175.40: seq=3 ttl=255 time=3.768 ms
64 bytes from 192.168.175.40: seq=4 ttl=255 time=11.999 ms
64 bytes from 192.168.175.40: seq=5 ttl=255 time=4.310 ms
64 bytes from 192.168.175.40: seq=6 ttl=255 time=3.267 ms
64 bytes from 192.168.175.40: seq=7 ttl=255 time=5.250 ms
64 bytes from 192.168.175.40: seq=8 ttl=255 time=3.513 ms
64 bytes from 192.168.175.40: seq=9 ttl=255 time=7.566 ms
64 bytes from 192.168.175.40: seq=10 ttl=255 time=5.697 ms
64 bytes from 192.168.175.40: seq=11 ttl=255 time=11.565 ms
64 bytes from 192.168.175.40: seq=12 ttl=255 time=8.813 ms
64 bytes from 192.168.175.40: seq=13 ttl=255 time=4.560 ms
64 bytes from 192.168.175.40: seq=14 ttl=255 time=3.600 ms
64 bytes from 192.168.175.40: seq=15 ttl=255 time=19.717 ms
64 bytes from 192.168.175.40: seq=16 ttl=255 time=3.496 ms
64 bytes from 192.168.175.40: seq=17 ttl=255 time=7.183 ms
64 bytes from 192.168.175.40: seq=18 ttl=255 time=4.932 ms
64 bytes from 192.168.175.40: seq=20 ttl=255 time=57.415 ms
64 bytes from 192.168.175.40: seq=21 ttl=255 time=3.462 ms
64 bytes from 192.168.175.40: seq=22 ttl=255 time=3.310 ms
64 bytes from 192.168.175.40: seq=23 ttl=255 time=3.854 ms
64 bytes from 192.168.175.40: seq=24 ttl=255 time=5.504 ms
64 bytes from 192.168.175.40: seq=25 ttl=255 time=4.530 ms
64 bytes from 192.168.175.40: seq=26 ttl=255 time=5.858 ms
64 bytes from 192.168.175.40: seq=27 ttl=255 time=3.758 ms
64 bytes from 192.168.175.40: seq=28 ttl=255 time=4.494 ms
64 bytes from 192.168.175.40: seq=29 ttl=255 time=3.406 ms
64 bytes from 192.168.175.40: seq=30 ttl=255 time=4.946 ms
64 bytes from 192.168.175.40: seq=31 ttl=255 time=6.621 ms
64 bytes from 192.168.175.40: seq=32 ttl=255 time=4.926 ms
64 bytes from 192.168.175.40: seq=33 ttl=255 time=13.401 ms
64 bytes from 192.168.175.40: seq=34 ttl=255 time=6.044 ms
64 bytes from 192.168.175.40: seq=35 ttl=255 time=4.301 ms
64 bytes from 192.168.175.40: seq=36 ttl=255 time=3.674 ms
64 bytes from 192.168.175.40: seq=37 ttl=255 time=6.356 ms
64 bytes from 192.168.175.40: seq=38 ttl=255 time=6.766 ms
64 bytes from 192.168.175.40: seq=39 ttl=255 time=3.551 ms
64 bytes from 192.168.175.40: seq=40 ttl=255 time=13.912 ms
64 bytes from 192.168.175.40: seq=41 ttl=255 time=3.765 ms
64 bytes from 192.168.175.40: seq=42 ttl=255 time=3.870 ms
64 bytes from 192.168.175.40: seq=43 ttl=255 time=4.685 ms
64 bytes from 192.168.175.40: seq=44 ttl=255 time=4.857 ms
64 bytes from 192.168.175.40: seq=45 ttl=255 time=4.789 ms
64 bytes from 192.168.175.40: seq=46 ttl=255 time=11.683 ms
64 bytes from 192.168.175.40: seq=47 ttl=255 time=3.243 ms
64 bytes from 192.168.175.40: seq=48 ttl=255 time=8.494 ms
64 bytes from 192.168.175.40: seq=49 ttl=255 time=3.840 ms
^C
--- 192.168.175.40 ping statistics ---
50 packets transmitted, 49 packets received, 2% packet loss
round-trip min/avg/max = 3.243/6.941/57.415 ms

Maybe that is corresponding to the graphs in the UniFi controller?

If you find how to solve this, I would be immensely grateful.
@s-hadinger If you have any ideas, I would be gratefull as well...

Sebastian

[Bascht74]

Instead of ping I set TelePeriod 10 for the device 192.168.175.40

now changed to a rule:
ON Time#Minute DO Backlog Publish stat/topic/Test {"1"};delay 50;Publish stat/topic/Test {"2"};delay 50;Publish stat/topic/Test {"3"};delay 50;Publish stat/topic/Test {"4"};delay 50;Publish stat/topic/Test {"5"};delay 50;Publish stat/topic/Test {"6"};delay 50;Publish stat/topic/Test {"7"};delay 50;Publish stat/topic/Test {"8"};delay 50;Publish stat/topic/Test {"9"};delay 50;Publish stat/topic/Test {"10"};delay 50;Publish stat/topic/Test {"11"} ENDON

[Bascht74]

With that, I see a lot less retransmissions. I will keep that running the next 24 hours. I know it is not a solution, but it maybe track in the right direction.

The retransmissions itself are very interessting:

Here you see that the device (.40) is sending a MQTT to the broker (.214). The broker is answering, BUT the device (.40) is not getting the ACK (Acknowledgement), so after 2 seconds it re-sent the package and the broker resent the ACK.
I think that shows, that sometimes the device doesn't get the sent frame.

Here is another example:

Seb

[Jason2866]

Which values have you tried with Setoption41 ?

[Bascht74]

I tried Setoption41 5 (I tried as well 10, 60)

But the screenshots above was with Setoption41 0

Could it be that the following issue esp8266/Arduino#6886 (comment) affects other communication like mqtt, ping, http-requests as well?

unifi shows devices with retransmission problems like this:
2020-12-27 16:55:38 User.Info 192.168.175.205 Dec 27 16:55:38 e063da538609,UAP-HD-IW-5.43.19+12493: : mcad[25619]: wireless_agg_stats.log_sta_anomalies(): bssid=e2:63:da:33:86:0a radio=ra0 vap=ra3 sta=d8:bf:c0:de:68:e3 satisfaction_now=60 anomalies=low_phy_rate tcp_latency
2020-12-27 16:56:38 User.Info 192.168.175.205 Dec 27 16:56:38 e063da538609,UAP-HD-IW-5.43.19+12493: : mcad[25619]: wireless_agg_stats.log_sta_anomalies(): bssid=e2:63:da:33:86:0a radio=ra0 vap=ra3 sta=d8:bf:c0:de:68:e3 satisfaction_now=71 anomalies=low_phy_rate tcp_latency

[Jason2866]

Tasmota does not use sleep function from espressif in standard setup. Tasmota has its own sleep routine not entering any of the sleep states from the chip
Does the Unify firmware has ARP treatment for power saving devices? Without this function Setoption41 is necessary to keep the connection alive

[Bascht74]

Tasmota does not use sleep function from espressif in standard setup. Tasmota has its own sleep routine not entering any of the sleep states from the chip

OK. Thanks for the information. Is this the routine that I can disable with sleep 0?
I tried that and it does not change the behavior.
I have sleep on default (50) and setoption60 0 as well as setoption41 60
Is there any way to "debug" the sleep routine?

Does the Unify firmware has ARP treatment for power saving devices? Without this function Setoption41 is necessary to keep the connection alive

Yes. I know. I have setoption41 60 set on all devices. These devices have tcp retransmissions, but no ARP problems (they are answering to Who is?). The two devices with much less tcp retransmissions I set setoption41 0 and a rule ON Time#Minute DO Backlog Publish stat/topic/Test {"1"};delay 50;Publish stat/topic/Test {"2"};delay 50;Publish stat/topic/Test {"3"};delay 50;Publish stat/topic/Test {"4"};delay 50;Publish stat/topic/Test {"5"};delay 50;Publish stat/topic/Test {"6"};delay 50;Publish stat/topic/Test {"7"};delay 50;Publish stat/topic/Test {"8"};delay 50;Publish stat/topic/Test {"9"};delay 50;Publish stat/topic/Test {"10"};delay 50;Publish stat/topic/Test {"11"} ENDON to keep the incoming communication of device going every 5 seconds.

I don't know why, but If you get incoming tcp-traffic every e.g. 5 seconds, there are much less tcp dropouts/retransmissions. the mqtt-keepalive from mosquito (30 seconds) is not enough.
If you try setoption41 5 that does not help as there is only outgoing traffic, but no incoming traffic.

In wireshark you can see the arp messages of setoption41 60:

Here you see another device sending the arp broadcast, and shortly after that a retransmission (because trasmote did not sent the ack or did not process the incoming packet):

If you ping the device, you get the long ping times...

Ping wird ausgeführt für 192.168.175.217 mit 32 Bytes Daten:
Antwort von 192.168.175.217: Bytes=32 Zeit=258ms TTL=255
Antwort von 192.168.175.217: Bytes=32 Zeit=309ms TTL=255
Antwort von 192.168.175.217: Bytes=32 Zeit=516ms TTL=255
Antwort von 192.168.175.217: Bytes=32 Zeit=3ms TTL=255

in wireshark:

a couple of minutes later you get long ping times again:

[Bascht74]

Next steps for me to try:

1. Disable Setoption41 -> 0 and disable mqtt messages, so that there are no transmissions. Check weather it changes the behaviour.
2. Try older Tasmota Releases, and check, if the retransmission are gone.
   core 2.7.2 --> Tasmota v8.4.0
   core 2.6.2 --> Tasmota v8.2.0 oder Tasmota v8.1.0 Doris
   core 2.4.2 --> Sonoff-Tasmota v6.4.1
   core 2.3.0 --> Sonoff-Tasmota v6.6.0
   core 2.3.0 --> Sonoff-Tasmota v6.2.1
3. Try NodeMCU, because they use NONOS SDK 3.0.x and probably other sleep routines.

[Bascht74]

Here is an interesting one:

The Tasmota device (192.168.175.212) sends an ping request to the broker (.214, packet 2092). The broker sends ACK (2903) and an ping response (2094). But the tasmota device is not ACK that response so that the broker sends a first retransmission (Packet 2100, after 429 ms). But the device is still not answering that response so that a second retransmission is sent, 832 ms after the first retransmission (packet 2110).
Then the device sends the missing ACK 159 ms later (Packet 2116) and than again a Dup ACK right away.

That means to my opinion that a least both (re)transmissions were received! But somehow it took over a second for the device to get the ACK answer ready or to process these transmissions. from the broker

Second example:

Here the device (.212) published in packet 4187 and got with 4188 a ACK-response. But it seems like it has not processed that ACK-response, so the device sent the packet again, 1.425 s later. The broker sent and DUP-ACK because of that and this time the device processed it.

Combining these to examples together it looks like the incoming packets are sometimes hold back from processing (and not being sucked up).

@Jason2866: Is there any way to disable any Sleep code or to log that (e.g. that the wifi code was executed every 50ms and how long it took)?
Do you have any idea how to log the incoming / outgoing tcp packets from the device side so that we see what the device sees? Maybe the device is seeing the packets in that strange way and that would help figuring out what is going on.

I don't see any retransmissions in a 20 minute period with the original shelly firmware, only with Tasmota.

Sebastian

Sebastian

[Jason2866]

SetOption60 0 and Sleep 0 is disabling any sleep.
@s-hadinger can help for logging.
Comparing with Shelly firmware does not help. We have no sources and we dont know with which SDK it is build.

[s-hadinger]

That's very interesting. I have seen contradictory behavior about Sleep 0. In my experience it created a lot of Wifi disturbance and made the device very hard to connect to. I thought that Tasmota wouldn't leave enough cpu time for Wifi SDK to handle packets.

BUT... Some users have seen the opposite, Sleep 0 would fix some Wifi connectivity issues.

Would you be kind enough to try Sleep 0 and report if it changes anyhting?

[Bascht74]

the documentation:
LoadAvg | Reported % time of Sleep spent doing Tasmota main loop processing

with sleep 200 I get:
Sleep":200,"LoadAvg":6

with sleep 50 I get:
"Sleep":50,"LoadAvg":19

If the main task of tasmota takes 19% of a 50ms period (9,5ms), why does it give the device no room with sleep 0 to process the other tasks?
Could the answer be, that the main task takes much more processing time from time to time?
Then sleep < 50 increases the probability, and sleep > 50 decreases it.

Is there a way so "log" the processing time of the main task?

• start & duration via serial output
• log if the main task takes over e.g. 15 ms or if the next "slot" calculated with the duration and the sleep time is missed?

Before I saw something at the shutter log of @stefanbode. With weblog 4 the device should log every movement (every 50ms), but it "misses" some from time to time (when the shutter stopped).

Sebastian

[Bascht74]

no more mqtt restarts after set sleep to 50.
Now setting sleep to 150 at 23:06

[Bascht74]

higher sleep changes nothing to the output.

In my experience it created a lot of Wifi disturbance and made the device very hard to connect to.
@s-hadinger what you observe with sleep 0 must be those "hick-ups" I was showing above. I think we need some more logging...
when I enter weblog 4 I get some messages like:
00:34:17.211 ADE: 6228804, 4475, [1773, -43, 657, 5], [1773, -8, 657, 3]
00:34:17.214 ADE: U 6228804, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
00:34:18.211 ADE: 6229575, 4474, [1773, 3, 657, 37], [1773, 16, 657, -36]
00:34:18.214 ADE: U 6229575, C 4474, I 0 + 0 = 0, P 0 + 0 = 0

What do they mean? Are they in any interest?
I think we need to figure out, why sleep 0 makes so much problems with transmissions...

[Bascht74]

Now I have the web inferface runing with sleep 0.
So Tasmota is running constantly (if I understand correctly) and the web interface and mqtt is sending a lot of packets.

I see now a lot of defective network traffic...

How does the coordination of the Tasmota main task and the "rest" work?

[Bascht74]

I got some logs now:

with sleep 0

00:54:41.535 MQT: Verbindungsversuch...
00:54:41.746 MQT: Verbindung fehlgeschlagen aufgrund von 192.168.175.214:1883, rc -2. Wiederversuch in 10 s
00:54:46.378 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/STATE = {"Time":"2020-12-30T00:54:46.374","Uptime":"2T01:13:12","UptimeSec":177192,"Heap":27,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"MqttCount":26,"POWER":"ON","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":60,"Signal":-70,"LinkCount":1,"Downtime":"0T00:00:03"}}
00:54:46.387 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/SENSOR = {"Time":"2020-12-30T00:54:46.382","ANALOG":{"Temperature":39.4},"ENERGY":{"TotalStartTime":"2020-12-09T09:59:34","Total":0.151,"Yesterday":0.038,"Today":0.005,"Period":0,"Power":5,"ApparentPower":7,"ReactivePower":5,"Factor":0.69,"Voltage":246,"Current":0.029},"TempUnit":"C"}
00:54:52.535 MQT: Verbindungsversuch...
00:54:52.746 MQT: Verbindung fehlgeschlagen aufgrund von 192.168.175.214:1883, rc -2. Wiederversuch in 20 s

The same time on the network side:

As you can see, there is no communication from the device to the network and it doesn't answer. So the complete communication seems to be down.

The next log:

00:55:13.535 MQT: Verbindungsversuch...
00:55:13.752 MQT: Verbindung fehlgeschlagen aufgrund von 192.168.175.214:1883, rc -2. Wiederversuch in 30 s
00:55:16.378 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/STATE = {"Time":"2020-12-30T00:55:16.374","Uptime":"2T01:13:42","UptimeSec":177222,"Heap":26,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"MqttCount":26,"POWER":"ON","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":62,"Signal":-69,"LinkCount":1,"Downtime":"0T00:00:03"}}
00:55:16.385 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/SENSOR = {"Time":"2020-12-30T00:55:16.381","ANALOG":{"Temperature":39.5},"ENERGY":{"TotalStartTime":"2020-12-09T09:59:34","Total":0.151,"Yesterday":0.038,"Today":0.005,"Period":0,"Power":5,"ApparentPower":7,"ReactivePower":5,"Factor":0.71,"Voltage":246,"Current":0.029},"TempUnit":"C"}
00:55:26.378 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/STATE = {"Time":"2020-12-30T00:55:26.374","Uptime":"2T01:13:52","UptimeSec":177232,"Heap":27,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"MqttCount":26,"POWER":"ON","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":58,"Signal":-71,"LinkCount":1,"Downtime":"0T00:00:03"}}
00:55:26.386 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/SENSOR = {"Time":"2020-12-30T00:55:26.381","ANALOG":{"Temperature":39.6},"ENERGY":{"TotalStartTime":"2020-12-09T09:59:34","Total":0.151,"Yesterday":0.038,"Today":0.005,"Period":0,"Power":5,"ApparentPower":7,"ReactivePower":5,"Factor":0.70,"Voltage":246,"Current":0.030},"TempUnit":"C"}
00:55:27.615 RSL: stat/Lampe.EG.Wohnzimmer.Weihnachtsstern/RESULT = {"Sleep":{"0":{"Active":"0"}}}
00:55:36.377 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/STATE = {"Time":"2020-12-30T00:55:36.374","Uptime":"2T01:14:02","UptimeSec":177242,"Heap":27,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"MqttCount":26,"POWER":"ON","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":62,"Signal":-69,"LinkCount":1,"Downtime":"0T00:00:03"}}
00:55:36.385 RSL: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/SENSOR = {"Time":"2020-12-30T00:55:36.381","ANALOG":{"Temperature":39.6},"ENERGY":{"TotalStartTime":"2020-12-09T09:59:34","Total":0.151,"Yesterday":0.038,"Today":0.005,"Period":0,"Power":5,"ApparentPower":7,"ReactivePower":5,"Factor":0.69,"Voltage":246,"Current":0.030},"TempUnit":"C"}

on the network side:

It says that it is trying to connect, but there is no outgoing packets for that connection.

The next try is successful:

00:55:44.535 MQT: Verbindungsversuch...
00:55:45.393 MQT: verbunden
00:55:45.400 MQT: tele/Lampe.EG.Wohnzimmer.Weihnachtsstern/LWT = Online (beibehalten)
00:55:45.404 MQT: cmnd/Lampe.EG.Wohnzimmer.Weihnachtsstern/POWER = 

on the network side:

[Jason2866]

Can you try this tasmota firmware? Based on latest development version. It is builded with latest Arduino ESP8266 core stage version and latest gcc build chain.

Ping-Statistik für 192.168.2.146:
    Pakete: Gesendet = 534, Empfangen = 534, Verloren = 0
    (0% Verlust),
Ca. Zeitangaben in Millisek.:
    Minimum = 1ms, Maximum = 291ms, Mittelwert = 3ms

tasmota.bin.gz

[Bascht74]

There is one noticeable detail that shows that something has been changed:

Here is one device with the current DEV firmware from yesterday:

Here is the device with the test firmware:

The RTT of the ACK packet from the Tasmota device to the broker (192.168.175.119 -> .114) is much longer ...

But so far only two retransmissions because of that:

ARP traffic is fine and has the same characteristics:

so far no problems with ping:

Webinterface still responsive...

[Bascht74]

UPDATE 21:12

RRT from the broker:

(the peaks are when the broker gets a MQTT Publish Message (STATE) every 300 seconds)

RRT from the device itself:

It somehow got better after 2.200 seconds...
I look in the packets if I can see something that made it better, but I found nothing special.
The only things noticeable are the two retransmissions. The second one was right before the RRT got better !?!

RRT from a other device with the dev-firmware from yesterday and a rule that sends an mqtt-message every 5 seconds to keep the device busy:

[Bascht74]

now the device with the test firmware got much worse again:

the other way around (from the broker) is still OK:

Are you using any real time information (I mean the current time from the NTP-Server for your sleep routine?
I'm curious because I've seen this behavior of "gets better" and "gets worse again" on other devices as well and they sometimes show the same pattern in the "UniFi graphs" at the same times....
Of course, this can be a coincidence or due to something else, but it is noticeable...

Sebastian

[s-hadinger]

Thanks for all this information. It's still a complete mystery.

Did you turn off Wemo/Hue emulation? I.e. disable UDP Multicast traffic ?

[Bascht74]

23:26:11.150 CMD: emulation
23:26:11.157 MQT: stat/Lampe.Test/RESULT = {"Emulation":0}

Is there a way to set the time manually?

[Jason2866]

And for me the mystery is that none of my devices does behave like this. Did ping test to devices
which are running since the last update (a few days ago) and the have a similar ping response as i already posted. It has to be a coincedence of the implementation of the wifi AP software and Tasmota
EDIT: I have enabled HueEmulation on some of this devices. No problem

[Jason2866]

Yes with command time

Time <value> = disable NTP and set UTC time as epoch value if greater than 1451602800 (January 1, 2016)

[Bascht74]

@Jason2866 thanks! "epoch", OK...

[Bascht74]

@Jason2866

If I use sleep 0 the LoadAvg is 663.
With sleepmode 50 I get an LoadAvg of 19. That means - if I understand right - that the main loop of Tasmota is 19% of 50ms = 9,5ms
If 9,5 ms is right the AvgLoad with sleep 0 should be 950 according to the code:

  uint32_t my_sleep = millis();
[...] (stuff happens)
  uint32_t my_activity = millis() - my_sleep;
[...]
  if (!my_activity) { my_activity++; }             // We cannot divide by 0
  uint32_t loop_delay = TasmotaGlobal.sleep;
  if (!loop_delay) { loop_delay++; }               // We cannot divide by 0
  uint32_t loops_per_second = 1000 / loop_delay;   // We need to keep track of this many loops per second
  uint32_t this_cycle_ratio = 100 * my_activity / loop_delay;
  TasmotaGlobal.loop_load_avg = TasmotaGlobal.loop_load_avg - (TasmotaGlobal.loop_load_avg / loops_per_second) + (this_cycle_ratio / loops_per_second); // Take away one loop average away and add the new one

If the LoadAvg with sleep 0 is "only" 663, this must mean that this is an indicator of the other stuff going on between the loops. Is that right?

But we can see that with sleep 0 the wifi / mqtt is not behaving right (at least with my setup).
And the extent changes from time to time.

I have noted a few more questions that are bothering me. I hope no one feels offended that these are only a few basic questions. After all, sometimes it's the simple things, so we should check those off first....

1. Can we count the number in which Tasmota main loop takes longer than 50 ms?
   from https://arduino-esp8266.readthedocs.io/en/latest/reference.html#timing-and-delays :
   Remember that there is a lot of code that needs to run on the chip besides the sketch when WiFi is connected. WiFi and TCP/IP libraries get a chance to handle any pending events each time the loop() function completes, OR when delay is called. If you have a loop somewhere in your sketch that takes a lot of time (>50ms) without calling delay, you might consider adding a call to delay function to keep the WiFi stack running smoothly.
2. Can we measure the min / max / avg time, the "other" code is executed after the loop? This way we could see how/if it changes if you use sleep 0 or sleep 50
3. Is the main loop triggering or activating any interrups that could cause the wifi code to break? --> https://arduino-esp8266.readthedocs.io/en/latest/reference.html#interrupts
   Long-running (>1ms) tasks in interrupts will cause instabilty or crashes. WiFi and other portions of the core can become unstable if interrupts are blocked by a long-running interrupt.
4. Could a delayMicroseconds in the Tasmota code go sometimes above 20 ms? --> from https://arduino-esp8266.readthedocs.io/en/latest/reference.html#timing-and-delays :
   The delayMicroseconds function, on the other hand, does not yield to other tasks, so using it for delays more than 20 milliseconds is not recommended.

If all of that doesn't help: could we ask the Arduino guys, if they have any idea?

Because of all the questions and you said, that you don't have the problems, I will start from scratch:

1. I leave the new test firmware on my device
2. I do a reset 5 and open the web interface. Check if there are any anomolys in the tcp traffic.
3. I will set sleep 0, because there is the most trouble and check if there are any anomolys in the tcp traffic.
4. I will setup my device slowly and check every time, if there are any anomolys in the tcp traffic.

Maybe there a no network problems at the beginning. If true, I will see, when that changes...

Can you tell me what wifi router/ap you are using and which device, that has no such problems that I am facing?

Sebastian

[Bascht74]

No trying sleep 250 and SetOption60 1

[Bascht74]

With that we see a nice pattern! The RTT goes down over time ... and then instantly up again and then down again and so on...

[Bascht74]

@Jason2866 Could this pattern when set sleep 250 and SetOption60 1 have something todo with

Tasmota/tasmota/support_wifi.ino

Line 141 in 165c6fd

void WiFiSetSleepMode(void)

?

[Bascht74]

After some time / Now it behaves still the same:

[Bascht74]

Changed the DTIM Values from 3 to 1:

Same pattern, now changing FTIM Values higher...

Changed from 1 to 30, nothing changed.
Now changed sleep from 250 to 200, 150, now 50. Nothing changed.

Now changing to sleep 0 and setoption60 1 at time around 4.800:

I found that comments about ARP / WIFI problems:
esp8266/Arduino#6886 (comment)
esp8266/Arduino#6886 (comment)
esp8266/Arduino#5998 (comment)
esp8266/Arduino#5825 (comment)
esp8266/Arduino#5825 (comment)
esp8266/Arduino#5784 (comment)
esp8266/Arduino#4332 (comment)
https://github.com/esp8266/Arduino/blob/master/libraries/esp8266/examples/LowPowerDemo/LowPowerDemo.ino

from: https://blog.voneicken.com/2018/lp-wifi-esp8266-assoc/
A perhaps extreme test is to ping the esp8266 every second. In that case it never goes to sleep at all, keeping the receiver going at 70mA full-time!

[Jason2866]

When sleep 0 LoadAvg is not valid anymore. You have to ignore.
As long LoadAvg has normal values the wifi part of the ESP has enough time
I am quite sure the problem is not in this part. If this would be the case all users would have problems.
My guess the issue is in nonos-sdk (closed source) and affects only specific combinations

[Jason2866]

Maybe it is worth to invest time in this direction https://forum.turris.cz/t/solution-found-for-wifi-clients-disconnects/6065

[Bascht74]

Hi @Jason2866 : Thanks, I will look into it. So far I know that I prevent WIFI_LIGHT_SLEEP if I do a rule with a 5 second delay command for 60 seconds, every minute. That way, the device is much more responsive. I will look into that shortly, setting up a possibility to compile Tasmota myself to check out some settings...

Maybe it is with UNIFI-Devices (I have IW-HD and Nano-HD, which obviously had some problems in the past).
Could you tell me what AP / Router you are using for WIFI?
Then I'll get one on Amazon and check if it helps.

Thanks in advance,

Sebastian

[Jason2866]

I have not only one ;-). My router is bintec elmeg router (Digitalisierungsbox premium OEM Telekom)
two bintec elmeg APs (W2003ac and W1001n), one Lancom LN-830acn and two MI Router 4A Gigabit Edition flashed with OpenWRT. All connected directly to the router or with a Lancom PoE switch.
My Tasmota devices are connected to all of this APs. None has a issue.