search

openshwprojects / OpenBK7231T_App

Open source firmware (Tasmota/Esphome replacement) for BK7231T, BK7231N, BL2028N, T34, XR809, W800/W801, W600/W601, BL602 and LN882H
https://openbekeniot.github.io/webapp/devicesList.html
1.48k stars 276 forks source link

NTP startup delay #807

Open ostat opened 1 year ago

ostat commented 1 year ago

Describe the bug On boot it currently takes about 15-20 seconds for the NTP event to fire. Is there anything we can do to reduce this? This becomes noticeable when using waitFor NTPState 1.

Firmware:

To Reproduce Steps to reproduce the behavior:

  1. Enable NTP
  2. Check the logs for first NTP message

Additional context Checking the logs, it looks like:

Info:MAIN:Time 9, idle 0/s, free 83920, MQTT 0(0), bWifi 0, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTING - 1
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MAIN:Time 10, idle 131029/s, free 83952, MQTT 0(0), bWifi 1, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Time 15, idle 248651/s, free 83712, MQTT 1(1), bWifi 1, secondsWithNoPing -1, socks 3/38 
Info:NTP:Seconds since Jan 1 1900 = 3891371204
Info:NTP:Unix time  : 1682418404
Info:NTP:Local Time : 2023/04/25 10:26:44
Info:MAIN:Time 16, idle 254748/s, free 83904, MQTT 1(1), bWifi 1, secondsWithNoPing -1, socks 2/38
openshwprojects commented 1 year ago

Hello, is quick connect enabled? Is static IP set?

ostat commented 1 year ago

Hi @openshwprojects. Is quick connect a setting in the device or on the network? I don't have have fixed or reserved IP's I don't normally do that for IOT devices.

openshwprojects commented 1 year ago

in obk web panel in flags, this should help a bit

I can see also a potential fix. We can speed up by 5 seconds.

Before fix - with quick connect and static IP - 7 seconds for NTP (NTP runs at 12 seconds total time), 5 seconds for wifi

ostat commented 1 year ago

Quick connect worked well, saved about 5 seconds. nice.

I also tried fixed IP, didn'e seem to make much difference, will prob leave it dynamic. Thanks for the Quick connect tip.

Info:MAIN:Time 4, idle 0/s, free 83904, MQTT 0(0), bWifi 0, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTING - 1
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MAIN:Time 5, idle 147622/s, free 83952, MQTT 0(1), bWifi 1, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MAIN:Time 10, idle 258006/s, free 83712, MQTT 1(2), bWifi 1, secondsWithNoPing -1, socks 3/38 
Info:NTP:Seconds since Jan 1 1900 = 3891396187
Info:NTP:Unix time  : 1682443387
Info:NTP:Local Time : 2023/04/25 17:23:07
Info:MAIN:Time 11, idle 269437/s, free 83904, MQTT 1(2), bWifi 1, secondsWithNoPing -1, socks 2/38
openshwprojects commented 1 year ago

After pushed fix that gives +5 extra second speedup, on N with static IP and quick connect flag, I get NTP on 7 seconds: image

@ostat hey, your log looks like you have multiple tabs with Web App open! This breaks log consistenty.

DeDaMrAzR commented 1 year ago

Also update to the latest build 1.17.46 to get even faster NTP response, static IP and quick connect are also options that will speed things up at boot.

image

ostat commented 1 year ago

After pushed fix that gives +5 extra second speedup, on N with static IP and quick connect flag, I get NTP on 7 seconds:

Will test soon thanks.

@ostat hey, your log looks like you have multiple tabs with Web App open! This breaks log consistenty.

Good eye, I edited the posted logs to keep only the relevant parts. Sorry for confusion.

ostat commented 1 year ago

This was I think too fast :). I am seeing an error NTP_SendRequest: Unable to send message, and then a delay of 60 seconds before retry.

Info:MAIN:Time 4, idle 0/s, free 84232, MQTT 0(0), bWifi 0, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTING - 1
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MQTT:mqtt_userName ...
Info:MQTT:Connect error in mqtt_client_connect - code: -4 (ERR_RTE)
Info:NTP:NTP_SendRequest: Unable to send message
Info:MAIN:Time 5, idle 141309/s, free 84280, MQTT 0(1), bWifi 1, secondsWithNoPing -1, socks 2/38 
...
Info:MAIN:Time 66, idle 256518/s, free 84040, MQTT 1(2), bWifi 1, secondsWithNoPing 1, socks 3/38 
Info:NTP:Seconds since Jan 1 1900 = 3891400555
Info:NTP:Unix time  : 1682447755
Info:NTP:Local Time : 2023/04/25 18:35:55
Info:MAIN:Time 67, idle 262644/s, free 84232, MQTT 1(2), bWifi 1, secondsWithNoPing 1, socks 2/38

Could we try a progressive backoff for the retry? Something like this.

g_ntp_delay = g_ntp_delay == 0 ? 1 
      : g_ntp_delay >= 30 ? 60 
      : g_ntp_delay + g_ntp_delay;

This should attempt to retry at 1 second, then 2, 4,8,16,32,60,60...

Edit: You only get this error when using DHCP. When I switched to static IP it didnt happen. Is it not waiting for the DHCP to setup?

openshwprojects commented 1 year ago

That's what I've been talking with @DeDaMrAzR . Ok, let me add a work around

DeDaMrAzR commented 1 year ago

Just to confirm the issue @ostat has. If DHCP is enabled that behavior is what occurs, with static IP everything is working.

openshwprojects commented 1 year ago

i pushed a condition to retry within 0 seconds as long as uptime is lower than 60, let's hope it wont break anything

ostat commented 1 year ago

That worked, and now NTP is connecting in 7 seconds, which is awesome (now I don't have to explain to my partner why we need to wait for the light to boot up ;)).

RE the fix, I notice in the logs there are two Main_OnWiFiStatusChange - WIFI_STA_CONNECTED. The first appears to be raised in error. Its indicating that the WIFI is ready when its not. 

Info:MAIN:Time 4, idle 0/s, free 84232, MQTT 0(0), bWifi 0, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTING - 1
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MQTT:mqtt_userName ...
Info:MQTT:Connect error in mqtt_client_connect - code: -4 (ERR_RTE)
Info:NTP:NTP_SendRequest: Unable to send message
Info:MAIN:Time 5, idle 139183/s, free 84248, MQTT 0(1), bWifi 1, secondsWithNoPing -1, socks 2/38 
Info:MAIN:Main_OnWiFiStatusChange - WIFI_STA_CONNECTED - 4
Info:MQTT:mqtt_userName ...
Info:MAIN:Time 6, idle 238279/s, free 83824, MQTT 0(2), bWifi 1, secondsWithNoPing -1, socks 3/38 
Info:MAIN:Boot complete time reached (5 seconds)
Info:CFG:####### Set Boot Complete #######
Info:NTP:Seconds since Jan 1 1900 = 3891406178
Info:NTP:Unix time  : 1682453378
Info:NTP:Local Time : 2023/04/25 20:09:38
Info:MAIN:Time 7, idle 249655/s, free 84216, MQTT 0(2), bWifi 1, secondsWithNoPing -1, socks 2/38