High RTT (ping) on ESP32-based device

[DesertCat]

PROBLEM DESCRIPTION

High RTT (ping) on ESP32-based device (compared to ESP-8266 device)

$ ping -c 20 -i 0.5 192.168.11.165
PING 192.168.11.165 (192.168.11.165) 56(84) bytes of data.
64 bytes from 192.168.11.165: icmp_seq=1 ttl=255 time=95.9 ms
64 bytes from 192.168.11.165: icmp_seq=2 ttl=255 time=206 ms
64 bytes from 192.168.11.165: icmp_seq=3 ttl=255 time=152 ms
64 bytes from 192.168.11.165: icmp_seq=4 ttl=255 time=22.5 ms
64 bytes from 192.168.11.165: icmp_seq=5 ttl=255 time=240 ms
64 bytes from 192.168.11.165: icmp_seq=6 ttl=255 time=26.9 ms
64 bytes from 192.168.11.165: icmp_seq=7 ttl=255 time=57.7 ms
64 bytes from 192.168.11.165: icmp_seq=8 ttl=255 time=67.5 ms
64 bytes from 192.168.11.165: icmp_seq=9 ttl=255 time=78.6 ms
64 bytes from 192.168.11.165: icmp_seq=10 ttl=255 time=87.3 ms
64 bytes from 192.168.11.165: icmp_seq=11 ttl=255 time=4.58 ms
64 bytes from 192.168.11.165: icmp_seq=12 ttl=255 time=128 ms
64 bytes from 192.168.11.165: icmp_seq=13 ttl=255 time=140 ms
64 bytes from 192.168.11.165: icmp_seq=14 ttl=255 time=137 ms
64 bytes from 192.168.11.165: icmp_seq=15 ttl=255 time=70.3 ms
64 bytes from 192.168.11.165: icmp_seq=16 ttl=255 time=11.7 ms
64 bytes from 192.168.11.165: icmp_seq=17 ttl=255 time=64.8 ms
64 bytes from 192.168.11.165: icmp_seq=18 ttl=255 time=97.3 ms
64 bytes from 192.168.11.165: icmp_seq=19 ttl=255 time=119 ms
64 bytes from 192.168.11.165: icmp_seq=20 ttl=255 time=113 ms

--- 192.168.11.165 ping statistics ---
20 packets transmitted, 20 received, 0% packet loss, time 9518ms
rtt min/avg/max/mdev = 4.584/96.135/240.018/59.811 ms

Avg RTT = 96.1 ms

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

• Read the Contributing Guide and Policy and the Code of Conduct
• Searched the problem in issues
• Searched the problem in discussions
• Searched the problem in the docs
• Searched the problem in the chat
• Device used (e.g., Sonoff Basic): Sonoff DUAL R3
• Tasmota binary firmware version number used: 9.5.0.9
  • Pre-compiled tasmota32.bin
  • Self-compiled
• Flashing tools used: ESP-Flasher-Windows-x64.exe
• Provide the output of command: Backlog Template; Module; GPIO 255:

12:39:22.408 CMD: Backlog Template; Module; GPIO 255
12:39:22.489 RSL: RESULT = {"NAME":"Sonoff Dual R3 (ZCD)","GPIO":[32,0,0,0,7552,0,0,0,0,576,225,0,0,0,0,0,0,0,0,0,0,7296,7328,224,0,0,0,0,160,161,0,0,0,0,0,0],"FLAG":0,"BASE":1}
12:39:22.706 RSL: RESULT = {"Module":{"0":"Sonoff Dual R3 (ZCD)"}}
12:39:22.976 RSL: RESULT = {"GPIO0":{"32":"Button1"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"7552":"ZC Pulse"},"GPIO5":{"0":"None"},"GPIO6":{"0":"None"},"GPIO7":{"0":"None"},"GPIO8":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO11":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"576":"LedLink_i"},"GPIO14":{"225":"Relay2"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"0":"None"},"GPIO19":{"0":"None"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO24":{"0":"None"},"GPIO25":{"7296":"CSE7761 Tx"},"GPIO26":{"7328":"CSE7761 Rx"},"GPIO27":{"224":"Relay1"},"GPIO32":{"160":"Switch1"},"GPIO33":{"161":"Switch2"},"GPIO34":{"0":"None"},"GPIO35":{"0":"None"},"GPIO36":{"0":"None"},"GPIO37":{"0":"None"},"GPIO38":{"0":"None"},"GPIO39":{"0":"None"}}

• If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:

  Rules output here:

• Provide the output of this command: Status 0:

12:40:29.542 CMD: Status 0
12:40:29.551 RSL: STATUS = {"Status":{"Module":0,"DeviceName":"Освітлення гараж 2","FriendlyName":["Виїзд","Головний"],"Topic":"relay_g2","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[3,3,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0}}
12:40:29.560 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota32/release/tasmota32.bin","RestartReason":"Vbat power on reset","Uptime":"0T00:10:17","StartupUTC":"2021-10-17T11:30:12","Sleep":50,"CfgHolder":4617,"BootCount":21,"BCResetTime":"2021-10-15T19:21:18","SaveCount":169}}
12:40:29.576 RSL: STATUS2 = {"StatusFWR":{"Version":"9.5.0.9(tasmota)","BuildDateTime":"2021-09-27T12:34:21","Core":"1_0_7_4","SDK":"v3.3.5-245-g95097b38d","CpuFrequency":80,"Hardware":"ESP32-D0WD-V3","CR":"414/699"}}
12:40:29.586 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["iot_net",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C8000100060000005A0A000000000000","00000080","00006000","00004000"]}}
12:40:29.611 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":1258,"Free":1856,"Heap":177,"PsrMax":0,"PsrFree":0,"ProgramFlashSize":4096,"FlashSize":4096,"FlashFrequency":40,"FlashMode":3,"Features":["00000809","9FDAC787","00152001","B7F7BFCF","05DA9BC0","60360DC7","000840D2","20200000","0000402D"],"Drivers":"1,2,3,4,5,7,8,9,10,11,12,14,17,20,21,24,26,27,29,34,38,50,52","Sensors":"1,2,3,5,6,7,8,9,10,11,12,13,14,15,17,18,19,20,21,22,26,28,31,34,37,39,40,42,43,45,51,52,55,56,58,59,64,66,67,74,85,92,127"}}
12:40:29.626 RSL: STATUS5 = {"StatusNET":{"Hostname":"relay_g2","IPAddress":"192.168.11.165","Gateway":"192.168.11.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.11.1","DNSServer2":"0.0.0.0","Mac":"08:3A:F2:58:35:A7","Webserver":2,"HTTP_API":1,"WifiConfig":2,"WifiPower":17.0}}
12:40:29.636 RSL: STATUS6 = {"StatusMQT":{"MqttHost":"","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_5835A7","MqttUser":"DVES_USER","MqttCount":0,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
12:40:29.644 RSL: STATUS7 = {"StatusTIM":{"UTC":"2021-10-17T11:40:29","Local":"2021-10-17T12:40:29","StartDST":"2021-03-28T02:00:00","EndDST":"2021-10-31T03:00:00","Timezone":"+01:00","Sunrise":"07:14","Sunset":"17:56"}}
12:40:29.651 RSL: STATUS9 = {"StatusPTH":{"PowerDelta":[0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}}
12:40:29.665 RSL: STATUS10 = {"StatusSNS":{"Time":"2021-10-17T12:40:29","Switch1":"ON","Switch2":"ON","ENERGY":{"TotalStartTime":"2021-10-15T19:21:18","Total":0.000,"Yesterday":0.000,"Today":0.000,"Power":[0,0],"ApparentPower":[0,0],"ReactivePower":[0,0],"Factor":[0.00,0.00],"Frequency":0,"Voltage":0,"Current":[0.000,0.000]},"ESP32":{"Temperature":53.3},"TempUnit":"C"}}
12:40:29.681 RSL: STATUS11 = {"StatusSTS":{"Time":"2021-10-17T12:40:29","Uptime":"0T00:10:17","UptimeSec":617,"Heap":176,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":0,"POWER1":"OFF","POWER2":"OFF","Wifi":{"AP":1,"SSId":"iot_net","BSSId":"62:52:52:52:E1:94","Channel":8,"Mode":"11n","RSSI":88,"Signal":-56,"LinkCount":1,"Downtime":"0T00:00:07"}}}

• Set weblog to 4 and then, when you experience your issue, provide the output of the Console log:

  Console output here:

TO REPRODUCE

ping -c 20 -i 0.5 device.ip.address

EXPECTED BEHAVIOUR

Average RTT around 1-10 ms

SCREENSHOTS

If applicable, add screenshots to help explain your problem.

ADDITIONAL CONTEXT

1. Have multiple DUALR3 devices powered from different branches on nearly-same distance to WiFi AP with same issue
   Max RTT was 950 ms

2. Sometimes get Destination Host Unreachable messages

$ ping -c 20 -i 0.5 192.168.11.165
PING 192.168.11.165 (192.168.11.165) 56(84) bytes of data.
From 192.168.11.120 icmp_seq=1 Destination Host Unreachable
From 192.168.11.120 icmp_seq=2 Destination Host Unreachable
From 192.168.11.120 icmp_seq=3 Destination Host Unreachable
From 192.168.11.120 icmp_seq=4 Destination Host Unreachable
From 192.168.11.120 icmp_seq=5 Destination Host Unreachable
From 192.168.11.120 icmp_seq=6 Destination Host Unreachable
64 bytes from 192.168.11.165: icmp_seq=7 ttl=255 time=35.8 ms
64 bytes from 192.168.11.165: icmp_seq=8 ttl=255 time=137 ms
64 bytes from 192.168.11.165: icmp_seq=9 ttl=255 time=133 ms

3. Sleep settings:

13:08:35.938 CMD: setoption60
13:08:35.947 RSL: RESULT = {"SetOption60":"OFF"}
13:09:26.830 CMD: sleep
13:09:26.839 RSL: RESULT = {"Sleep":{"50":{"Active":"50"}}}

4. I have ESP8266-based device (Sonoff Slampher) in same network with Tasmota version 9.5.0 and default settings. Please compare ping results:

$ ping -c 20 -i 0.5 192.168.11.189
PING 192.168.11.189 (192.168.11.189) 56(84) bytes of data.
64 bytes from 192.168.11.189: icmp_seq=1 ttl=255 time=1.68 ms
64 bytes from 192.168.11.189: icmp_seq=2 ttl=255 time=1.52 ms
64 bytes from 192.168.11.189: icmp_seq=3 ttl=255 time=12.9 ms
64 bytes from 192.168.11.189: icmp_seq=4 ttl=255 time=1.67 ms
64 bytes from 192.168.11.189: icmp_seq=5 ttl=255 time=2.83 ms
64 bytes from 192.168.11.189: icmp_seq=6 ttl=255 time=2.65 ms
64 bytes from 192.168.11.189: icmp_seq=7 ttl=255 time=1.32 ms
64 bytes from 192.168.11.189: icmp_seq=8 ttl=255 time=2.28 ms
64 bytes from 192.168.11.189: icmp_seq=9 ttl=255 time=2.14 ms
64 bytes from 192.168.11.189: icmp_seq=10 ttl=255 time=1.86 ms
64 bytes from 192.168.11.189: icmp_seq=11 ttl=255 time=1.31 ms
64 bytes from 192.168.11.189: icmp_seq=12 ttl=255 time=1.79 ms
64 bytes from 192.168.11.189: icmp_seq=13 ttl=255 time=8.44 ms
64 bytes from 192.168.11.189: icmp_seq=14 ttl=255 time=1.48 ms
64 bytes from 192.168.11.189: icmp_seq=15 ttl=255 time=1.62 ms
64 bytes from 192.168.11.189: icmp_seq=16 ttl=255 time=1.67 ms
64 bytes from 192.168.11.189: icmp_seq=17 ttl=255 time=1.59 ms
64 bytes from 192.168.11.189: icmp_seq=18 ttl=255 time=2.15 ms
64 bytes from 192.168.11.189: icmp_seq=19 ttl=255 time=1.50 ms
64 bytes from 192.168.11.189: icmp_seq=20 ttl=255 time=1.89 ms

--- 192.168.11.189 ping statistics ---
20 packets transmitted, 20 received, 0% packet loss, time 9521ms
rtt min/avg/max/mdev = 1.314/2.722/12.990/2.788 ms

Avg RTT = 2.7 ms

5. Tried reset 3 to erase wi-fi calibration data and power-cycle device. No result.

(Please, remember to close the issue when the problem has been addressed)

[sfromis]

I'm also seeing longer ping times with ESP32, except for ESP32-C3, but don't see it as a "problem" for simple use cases.

[ascillato]

Tasmota devices are responsive but they also sleep so as to reduce energy consumption. If you want Tasmota to be awake all the time (consuming much more energy) and respond right away to any ping request, set sleep to 0. Go to the Tasmota console and type sleep 0.

This is not a bug. It is intended to be that way and it is configurable.

[DesertCat]

Thank you!

It may also be useful:
espressif/arduino-esp32#1484

[ascillato]

Thanks for the link but the sleep in Tasmota is different. In Tasmota is a custom sleep that is dynamic. Is not the one of the linked issue.

Tasmota allows you to use a dynamic sleep, a fixed sleep or not sleep at all.

For more information on that, please check Tasmota docs. Thanks.