Optimize dynamic sleep

[Bascht74]

Hi there,

now that I'm more involved with Tasmota, I'm also looking at the code.
I am not a programmer and therefore have limited skills as far as programming is concerned.

However, I noticed that the dynamic sleep mode does not always wait exactly 50ms with sleep 50, but sometimes a bit more.
I tried it myself (via Gitpot) to see if it could be better "aligned" and I had an idea.

However, I do not dare to create a pull request, because I never before did that with code.
So I write once my idea in here. If they are good (at least in part), perhaps someone can point me in the right direction how to incorporate them. I am ready to learn how to do a pull request, that is not directly crushed down because of beginners mistaces...

Here you can see the changes that I did:
Bascht74@571a8fd

1. I moved the code for the calculation of TasmotaGlobal.loop_load_avg to the beginning of the look, so that the time spent this calculations it is taken into account in the timing stuff.
   Currently this seems not to be the case. This causes the loops to shift a bit every time.

2. I have often seen that people replace simple if-loops with the following constructs (and they also simplify the code visually):
   uint32_t my_activity = millis() - my_sleep || 1; // We cannot divide by 0;

instead of:

uint32_t my_activity = millis() - my_sleep;
if (!my_activity) { my_activity++; };

I changed that, too for my changes, but I could easily can revert it as it is only optical stuff.

3. I optimized the code for SleepDelay, so that it always determines the next aligned "slot" and waits until then.
   This way, even with longer runtime, the time segments are kept much more exact than right now.
   This way no FUNC_EVERY_50_MSECOND will be skipped every now and then, as a cause of a missing alignment.

Example where you can see this quite well (looks clearer now as everything is executed almost the same time slot):

21:58:17.208 ADE: 6143462, 4474, [1773, -68, 649, -27], [1773, 0, 649, -5]
21:58:17.211 ADE: U 6143462, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
21:58:18.208 ADE: 6146203, 4474, [1773, 13, 649, 38], [1773, -5, 649, 7]
21:58:18.211 ADE: U 6146203, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
21:58:19.208 ADE: 6156133, 4474, [1773, -71, 650, 8], [1773, -11, 650, -13]
21:58:19.211 ADE: U 6156133, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
21:58:20.208 ADE: 6154742, 4474, [1773, -23, 650, -40], [1773, -2, 650, -5]
21:58:20.211 ADE: U 6154742, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
21:58:21.208 ADE: 6152291, 4473, [1773, -20, 650, 48], [1773, 26, 650, -2]
21:58:21.211 ADE: U 6152291, C 4473, I 0 + 0 = 0, P 0 + 0 = 0
22:01:09.419 MQT: tele/Geraet. Test/STATE = {"Time":"2021-01-02T22:01:09","Uptime":"0T00:05:09","UptimeSec":309,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":0,"MqttCount":1,"POWER1": "OFF","POWER2":"OFF","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":90,"Signal":-55,"LinkCount":1,"Downtime":"0T00:00:03"}}
22:01:09.452 MQT: tele/Geraet.Test/SENSOR = {"Time":"2021-01-02T22:01:09","Switch1":"OFF","Switch2":"OFF","ANALOG":{"Temperature":57.9},"ENERGY":{"TotalStartTime":"2020-12-31T13:46:15","Total":0.000,"Yesterday":0. 000,"Today":0.000,"Period":0,"Power":[0,0],"ApparentPower":[0,0],"ReactivePower":[0,0],"Factor":[0.00,0.00],"Voltage":0,"Current":[0.000,0.000]},"Shutter1":{"Position":0,"Direction":0,"Target":0},"TempUnit":"C"}
22:06:09.419 MQT: tele/Geraet. Test/STATE = {"Time":"2021-01-02T22:06:09","Uptime":"0T00:10:09","UptimeSec":609,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":0,"MqttCount":1,"POWER1": "OFF","POWER2":"OFF","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":92,"Signal":-54,"LinkCount":1,"Downtime":"0T00:00:03"}}
22:06:09.431 MQT: tele/Geraet.Test/SENSOR = {"Time":"2021-01-02T22:06:09","Switch1":"OFF","Switch2":"OFF","ANALOG":{"Temperature":60.0},"ENERGY":{"TotalStartTime":"2020-12-31T13:46:15","Total":0.000,"Yesterday":0. 000,"Today":0.000,"Period":0,"Power":[0,0],"ApparentPower":[0,0],"ReactivePower":[0,0],"Factor":[0.00,0.00],"Voltage":0,"Current":[0.000,0.000]},"Shutter1":{"Position":0,"Direction":0,"Target":0},"TempUnit":"C"}
22:11:09.419 MQT: tele/Geraet. Test/STATE = {"Time":"2021-01-02T22:11:09","Uptime":"0T00:15:09","UptimeSec":909,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":0,"MqttCount":1,"POWER1": "OFF","POWER2":"OFF","Wifi":{"AP":1,"SSId":"IOT-LOTZ","BSSId":"E2:63:DA:33:3C:3E","Channel":6,"RSSI":96,"Signal":-52,"LinkCount":1,"Downtime":"0T00:00:03"}}
22:11:09.431 MQT: tele/Geraet.Test/SENSOR = {"Time":"2021-01-02T22:11:09","Switch1":"OFF","Switch2":"OFF","ANALOG":{"Temperature":61.0},"ENERGY":{"TotalStartTime":"2020-12-31T13:46:15","Total":0.000,"Yesterday":0. 000,"Today":0.000,"Period":0,"Power":[0,0],"ApparentPower":[0,0],"ReactivePower":[0,0],"Factor":[0.00,0.00],"Voltage":0,"Current":[0.000,0.000]},"Shutter1":{"Position":0,"Direction":0,"Target":0},"TempUnit":"C"}

4. There is still one thing that is bugging me at the moment.:
   Is it really necessary to statically use delay(1) and if (Serial.available()) { break; } ) in those loops?
   If I get rid of the loop and use delay(mseconds) directly, e.g. the network response is much better and I don't see as many retransmissions on the network (only one from time to time).

Could this be solved in another way, e.g. only use that part if you really need it (e.g. only for a device that has serial TX/RX GPIO configured).

Sebastian

[Frogmore42]

I think you might be missing the point of my_activity. This is what you wrote:
uint32_t my_activity = my_activity || my_sleep + 1; // We cannot divide by 0;
As you have it written, you are setting the value of my_activity to an uninitialized value or my_sleep + 1, neither of those seem very correct.

My_sleep is not a great name. I think the intention of it is the start time of the routine the checks how much time we need to sleep. My_activity, calculates the elapsed time of the loop, i.e. the amount of time all the functions took. This is (from the original code):
uint32_t my_activity = millis() - my_sleep;
my_sleep was the counter at the start, and now it is checking the counter after all the activity. The difference is how long it took to do all the loop functions. The following then does the check for how long to wait:

   if (my_activity < (uint32_t)TasmotaGlobal.sleep) {
      SleepDelay((uint32_t)TasmotaGlobal.sleep - my_activity);  // Provide time for background tasks like wifi
    } else {

This check sets the SleepDelay to the expected value (50ms normally) but subtracts out the amount of time this loop took, so the next loop occurs at the right time. The last bit of code in the function is calculating the load average. It is not a lot of code, but it will increase the amount of time between loops (but it should be a pretty constant value).

For your #2, that is a personal preference. But, this one doesn't even appear to be necessary:
if (!my_activity) { my_activity++; } // We cannot divide by 0
my_activity is not the divisor in any of the following calculations.

For #3, the current code is already doing what you want.

For #4, there is always more than one way to do things. Tasmota is using the non-OS version of the ESP code. This means all tasks need to cooperate and NOT over use the CPU. While it probably would be possible to add a check to see if serial was enabled, it is not clear this is an easy check to make (given how much support for serial there is in Tasmota). Most of the time there is no serial available so that check is simple and then does nothing.

I am working on a project where timing is very important (integrating power to get energy). I am using CCOUNT to get the processor cycles that have transpired between now and the last time I checked. This allows it handle different loop timings and get the correct answer. But, even before I did that, I found the timing to be accurate.

How are you checking that the timing is off?
How much is it off?
How frequently?

[Frogmore42]

@Bascht74 I did not intend the above to come across as "crushing" you. I am definitely not an expert on Tasmota. (But I have submitted at least one PR and wrote the initial implementation of the SCD30 driver.) There is a significant learning curve to any complex system. It is great that you are taking the time to learn more and try things out.

I have not really looked to see if the every 50 millisecond events are happening every 50mS. If I was really interested in checking that out, I would create a driver that toggles a GPIO pin and hook that to the 50 mS event. I would then put an oscilloscope on the pin to see what it was doing. i have used this technique when bit-banging a GPIO pin to generate a custom signal.

[arendst]

Is it really necessary to statically use delay(1) and if (Serial.available()) { break; } ) in those loops?

Nice observation. The Tasmota code looks like this:

void SleepDelay(uint32_t mseconds) {
  if (mseconds) {
    for (uint32_t wait = 0; wait < mseconds; wait++) {
      delay(1);
      if (Serial.available()) { break; }  // We need to service serial buffer ASAP as otherwise we get uart buffer overrun
    }
  } else {
    delay(0);
  }
}

I chked the core code and found this for the esp8266:

int HardwareSerial::available(void)
{
    int result = static_cast<int>(uart_rx_available(_uart));
    if (!result) {
        optimistic_yield(10000);
    }
    return result;
}

and this for the esp32:

int HardwareSerial::available(void)
{
    return uartAvailable(_uart);
}

It seems the esp8266 available function does an inherited 1 millisecond delay (optimistic_yield(1000)) if nothing is available. Adding this to the tasmota routine delay(1) it waits 11 milliseconds (!) most of the time.

I'll change the code for the esp8266 allowing you to do some more tests.