MQTT Import and deep sleep

[arion_p]

Hi guys,

I'm trying to use MQTT import with deep sleep and retain flag to send commands/data from OpenHAB to ESPEasy. I have compiled my own version using v2.0-20180130 and P155 (HeatpumpIR).
I have setup some items in OpenHAB that, when changed, send their values with retain flag to MQTT broker on specific topics. I have setup MQTT Import to subscribe to those topics to get the values. Up to this point everything works as expected: I can change the items values in OpenHAB and the values are sent to ESPEasy and can trigger events/rules. If I turn ESPEasy off and then on, it gets the last posted values (retain flag works).

However as soon as I enable deep sleep, it no longer gets any values. I would expect that upon wakeup MQTT Import would subscribe to the configured topics, get the last posted values and then go to sleep again. However it does not - it merely subscribes to the topics and then immediately gos to sleep without getting any values. I have attached serial monitor through USB and enabled debug logging on serial and I can see that is actualy subscribes to the topics but does not get any values. I also notice that rules processing time varies betqeen 600 and 1500 ms

Is this setup supposed to work the way I expect? Am I doing something wrong? Is the long rules processing time possibly preventing MQTT Import from getting the values in time (before it goes to sleep)?

Thanks in advance for any help.

Edit:

Here is the relevant log:

Code: Select all

...
EVENT: Clock#Time=Tue,00:04
EVENT: Processing time:575 milliSeconds
IMPT : MQTT 037 Connection lost
IMPT : Connected to MQTT broker with Client ID=espeasy-Import      
IMPT : [heatpump#temp] subscribed to /espeasy/imp/LivingRoomAC/Temp
EVENT: System#Sleep
EVENT: Processing time:559 milliSeconds
SLEEP: Powering down to deepsleep...
state: 5 -> 0 (0)
...

Of course when deepsleep is off, after subscribing to /espeasy/imp/LivingRoomAC/Temp it laso gets the last value, but with deep sleep it goes directly to sleep.

[arion_p]

So, I guess no one is using MQTT Import along with deep sleep.

Anyway, had a look at the code in GitHub and as far as I can tell this cannot possibly work. Receiving values from MQTT uses a callback that is probably called from within PubSubClient.loop(). In MQTT Import plugin PubSubClient.loop() is called from PLUGIN_TEN_PER_SECOND, but the subscription is done in PLUGIN_ONCE_A_SECOND. Now when deep sleep is enabled, a single pass through all the periodic PLUGIN_xxx_SECOND calls is made and then the system goes to sleep. In this single pass PLUGIN_TEN_PER_SECOND is called before PLUGIN_ONCE_A_SECOND (see ESPEasy.ino lines 1354-1357). Hence after the subscription, loop() is never called and as a result there is no chance of ever getting any values from MQTT. Even if the order was reversed (i.e. loop() was called after the subscription) that would not ensure values are received as it takes some time for MQTT to process the subscription and send the values, and even the network packets take some time to be transmitted (not to mention that multiple values may be sent on different packets and I do not know if loop() processes more than one packet on each call).

I can see a few options here to make this work:

• There could be an option that would allow the user to specify a delay before going to sleep. If a delay is specified, a single pass would be executed upon wake up and then the loop would continue normally executing the required periodic calls at the correct intervals until the sleep delay has expired. Then the system would go to sleep.
• Another option would be to let plugins specify if the require such delayed processing (so that when none of the enabled plugins need delayed processing the system would revert to the current behaviour) and perhaps also specify the maximum time they need. Of course the user would also be able to apply an upper limit on this delay to allow better control of battery life. So if a plugin returns that it needs the system to be running for 10 sec on each wake up, but the user specifies a limit of 2 sec, then the system would only be kept running for 2 sec (ignoring the plugin request).
• A further improvement would be to also allow each plugin when it is done with its delayed processing and when all plugins have reported back that they are done, go to sleep immediately bypassing the configured delay. E.g MQTT IMport may specify that it needs 5 sec to make sure it can receive retained values after wake up and the user has specified a limit of 2 sec. Thus on each wake up the system would normally run for 2 sec then go back to sleep. However if MQTT Import has received a value for every topic it has subscribed to after say 500ms, there is no point waiting the full 2sec to go to sleep - the system can go to sleep immediately.

In addition to the above, I don't know what happens with timers set through rules. Maybe these should also extend the delay before sleep, or they could schedule an earlier wake up (just to process the timer). But this is another issue.

Also when the delayed sleep is used, the system still has to run a single pass on all periodic tasks once upon wake up, before it resumes the normal loop, to make sure they are all called at least once on every wake up

These are just some thoughts. Perhaps the developers of ESPEasy have other plans regarding this issue. If I find some free time I may try to implement some of these.

Arion_p

[TD-er]

Those are all usable ideas worth a test.
I guess the most flexible way would be to add 2 commands to the rules (and also the rules must be executed on wake):

• setGoToSleepTimer (quite the opposite of what we humans do ) to make sure the devices goes to sleep again if something may timeout.
• sleepNow

The last one could be the same command with argument 0, or the other way around set some timer in the rules that only execute sleepNow.

Then the sleep-timer should be adjustable to set to "disabled".

If you like this suggestion, or have another one, please also add this as a feature request on the GitHub issues list.

[arion_p]

Actually there is already a command to put system to sleep from a rule. The command is deepSleep and is effective immediatelly. As far as I can tell, deep sleep need not be enabled for this to work. It takes a parameter which is the number of seconds before the system wakes up again.

You can use rule timers to delay the sleep or any other trigger that is appropriate. The only issue is that rules timers have 1 sec resolution, so short delays (eg. 250 ms ) are not possible.

[TD-er]

I just made an enhancement for the deepsleep parameter in the settings.
It was a char treated as a boolean (enable/disable).
I changed it into 0 => disabled (same as before) and else the number of seconds de ESP should be awake between deep sleeps.

See pull request https://github.com/letscontrolit/ESPEasy/pull/1032

Perhaps you could test it?
Also added a number of events (see the pull req.) to be used in rules.

[arion_p]

That's great news. I will certainly give it a try and report back.

In the meantime I played a little with deepSleep command and rules. I disabled deep sleep from config and tried to get similar behaviour using rules. While it is possible, it is awkward and a lot of work if I want to implement all aspects that are already implemented in deep sleep setting. For example there need to be rules to delay sleep for 30 seconds after cold boot (not sure how to detect cold boot) and to disable sleep if GPIO16 is held high on boot.

I have one concern about your enhancement. There seems to be no way to get the previous behaviour (quickly run all tasks and go back to sleep without any delays) if needed. This would result in awake times usually less than 1 sec and hence longer battery life.

On a side note:

In my little project I wanted to get some settings from OpenHAB and send an IR command when one of those settings change. However it turns out that MQTT Import fires the device value changed event whenever it receives a value from MQTT, even if it is the same value. Even worse, when using deep sleep, the system is booting and initialized from scratch, which means it has no previous state and MQTT Import cannot possibly compare the new value received against the previous value in order to only fire the event on real change. To support that there are a few options:

• Save current values in RTC memory before sleep and restore them after boot.
  This is very problematic as RTC memory is limited (so you cannot statically assign a certain range to each plugin) and it is also hard to dynamically manage where the values are stored for each plugin (considering that you may also have multiple instances of each plugin
• Save the state in flash memory (file system) before sleep and restore it after boot.
  Depending on usage pattern this may cause unnecessary wear on the flash chip
• Send the previous values to MQTT on a separate related topic with retain flag set and retrieve them upon wakeup.
  Obviously this only works for MQTT Import. For every topic that MQTT Import subscribes to, it can use another shadow topic with the /lastvalue suffix to store the last value. This is not without its problems either. Upon wake up it cannot be guaranteed that /lastvalue will be received before the current value. Because of this the plugin will have to keep some state flag and check if the value has changed only after receiving both the current and the previous value. On every change (and preferably after the events have been processed) it can publish the current value as lastvalue in preparation for the next change

[grovkillen]

I have one concern about your enhancement. There seems to be no way to get the previous behaviour (quickly run all tasks and go back to sleep without any delays) if needed. This would result in awake times usually less than 1 sec and hence longer battery life.

Setting it up 0 gives the old behavior I think.

[arion_p]

Setting it up 0 gives the old behavior I think.

Actually setting it to 0 disables sleep altogether.

[grovkillen]

Ok, TD-er will need to get back on that.

[TD-er]

Maybe we could use the 1 as 'old behavior', since it is very likely the first time a check is done for deep sleep, 1 second has already passed.
Or stated otherwise, it is unlikely the loop() will be processed more than once in the first second.
Connecting to all the externals may take quite some time.

[arion_p]

Sounds like a reasonable assumption to me. Also MQTT Import will subscribe after the 1st second elapses which means it has little, if any, time left to receive any values if wake up time is set to just 1 second.

Another perhaps improvement would be to run all scheduled tasks once upon wake up like was done previously with deep sleep enabled.

[TD-er]

The check for deep sleep is at the end of the loop, so all is being handled at least as much as before.
It may be a little more, if it was handled within a second until the end of the first run of the loop, because then a second run of the loop is being started.
The set awake time is a minimum. It may take up to the run of one more loop to go to sleep again.

[arion_p]

The check for deep sleep is at the end of the loop, so all is being handled at least as much as before.

This is not entirely true. The check for deep sleep is done twice inside the loop, once at the top and once at the end of it. The first check shortcircuits any timouts and simply calls all 4 periodic handlers at once (wiithout the 1/50, 1/10, 1 and 30 second delay). The second call is used to actually put the system to sleep. By changing isDeepSleepEnabled() to return true only after the configured delay has passed, you essentially eliminate the shortcircuiting done by the first check. Upon wake up isDeepSleepEnabled() will always return false and the loop will follow the normal flow (honoring any delays). In fact the 30 second handler will not be called at all unless the awake timer is set to at least 30 seconds.

Now when the awake timer elapses there are two cases:

• The timer elapses after the second check and before the first check of the next iteration of the loop
  In this case isDeepSleepEnabled() will return true on the first check of the last loop and call all 4 handlers immediatelly
• The timer elapses between the first check and the second check of the same iteration of the loop
  In this case the first check will return false and not run all 4 handlers at once and the second check will put the system to sleep.

The probability of each of these cases depend on the amount of work the core does between successive calls of loop(). Normally most of the time should be spent within loop() not in between calls. Based on that assumption, the second case is the most probable one and the one that happens most of the time.
(Note: We can actually measure the probability by logging the time at the start and at the end of the loop. Taking the difference between one iteration's start time and the previous one's end time we can measure the time spent in the core. Taking the difference of the start and end time of the same iteration we can measure the time spent within the loop. By averaging those we can measure the ratio core/user time and hence the probability/frequency of each case)

As you can see before the change all handlers where called at once immediately after wake up and system put to sleep immediately. After the change, handlers are called at their scheduled times (for the 30 second handler that may be never) and depending on when exactly the awake timer elapses you may get a run of all 4 handlers just before sleep (but without any further time for processing / receiving data) or you may not (most of the time you will not).

[TD-er]

The check for deep sleep is at the end of the loop, so all is being handled at least as much as before.

This is not entirely true. [...]

Is this a better solution? https://github.com/letscontrolit/ESPEasy/pull/1047

[arion_p]

Yes, I think that'll work much better.

In the meantime I run some tests on the last version. I ended up setting the delay to 10 seconds to get MQTT Import to get a response. It seems the boot/connect process is taking quite some time and 10 seconds is marginally enough. Currently I only receive one value. If I add more I do not know if it will still be enough.

However what worries me is the the boot process does not have a fixed duration, mainly because of the wifi connection. The duration may vary, depending on the signal conditions. One has to either use a longer delay, which shortens battery life, or risk occasonally miissing values. On option would to start the delay after the boot procesess has finished and wifi connected.

[TD-er]

We could add a gotosleep command in the rules?
That way the maximum can be long(er), but it will be on only as long as needed.

If you like that idea, please add an issue for it on Github.

There seems to be another issue with the rules, since one of today's commits. See https://github.com/letscontrolit/ESPEasy/issues/1050
Maybe you can see the issue, 'cause I can't.

Also there have been some improvements on speed, which could lead to shorter "awake" times, although those will depend mostly on external factors.

[arion_p]

There is no need to add a new command as there already is one: deepSleep, and I have actually tested it and it works. The only problem with this is that it will not honor some special rules that isDeepSleepEnabled() does. In particular:

• After cold boot, isDeepSleepEnabled() will delay sleep for 30 seconds, deepSleep comand will go to sleep immediately regardless
• as long as GPIO16 is pulled low, isDeepSleepEnabled() will not go to sleep, deepSleep comand ignores GPIO16

I also noticed the speed improvements and they are quite impressive. I don't see why these would lead to shorter awake times, perhaps I am missing something. Unless of course you mean that we won't need as long awake times as we did without the speed improvements, which is true and a very good thing indeed (sorry if I have misinterpreted your comment)

I will take a look at the issue and see if I can spot anything.

[arion_p]

As a matter of fact there is an issue with this commit https://github.com/letscontrolit/ESPEas ... 62d5d3fde0.

If after wake up isDeepSleepEnabled() will return true for the first iteration of the loop enabling shortcircuit running all tasks. But this will also happen on all subsequent iterations of loop() until the awake time has elapsed. This means that on every loop all tasks will be called at once. Istead, what we need is that all tasks are run at once only on the first loop after wake up, while subsequent iterations should honor respective timeouts of each task.

We need a flag that is set in setup() and reset at the end of loop(). In the check for the shortcircuit run, use the flag to determine if this is the first iteration after wake up. Alternatively we can use a loop count if one exists already.

I think this is the cause of issue #1050

Sorry, I should have noticed this earlier.

[TD-er]

OK, I will look into the "run shortcut once" suggestion.
And also in the deepsleep command, which apparently should already be there.

My idea was to enable deepsleep with a set awake time of let's say 30 sec.
Then you could decide to send a deepsleep command in the rules whenever enough has been done.
Worst-case scenario is that the device will be up as long as the set awake time.

And more speed improvements are coming, although not as impressive as those from yesterday. (unless I will find something else )