nrf52 power regression using wait_ms

[NeilMacMullen]

Somewhere between commits 1863400 (5.8?) and 485bdee (5.9.4 RC) there has been a regression in the behaviour of wait_ms.

When tested on our nRF52 based board....

• When entering a "while (true) wait_ms(1000);" loop out board consumes >400uA.

• When this is replaced with "while (true) Thread::wait(1000)" idle power is reduced to ~4uA.

(In both cases, the code is called directly from main and no threads have been explicitly created.)

Compiler is GCC_ARM

My understanding was that wait_ms was the preferred alternative to Thread::wait ?

[NeilMacMullen]

copying @MarceloSalazar @marcuschangarm
[Mirrored to Jira]

[NeilMacMullen]

It seems that calling wait_ms even once is enough to cause the extra current draw. It looks like this is due to the call to ticker_read and presumably then firing up the ticker via mbed_ticker_api/initialize. I'm not sure what has changed in this area - is mbed now using some hungry internal clock or has the default frequency been increased. The use of a 1MHz default doesn't seem like a terribly low-power option.
[Mirrored to Jira]

[NeilMacMullen]

Just checked and the older (low power) firmware also uses 1MHz. I notice the RF52 us_ticker code has been substantially reworked but I can't spot any obvious breakages. I've confirmed that nrf_timer_task_trigger(NRF_TIMER1, NRF_TIMER_TASK_STOP/START) in hal_deepsleep are actually being called. I've also rebuild with release profile just in case there's some #ifdef somewhere I haven't spotted.
[Mirrored to Jira]

[NeilMacMullen]

Adding @mprse since he also seems to have touched this recently! :-)
[Mirrored to Jira]

[pan-]

@NeilMacMullen deepsleep is prevented by the wait API:

mbed-os/platform/mbed_wait_api_rtos.cpp

Lines 42 to 47 in 2a824a1

	if ((us >= 1000) && core_util_are_interrupts_enabled()) {
	// Use the RTOS to wait for millisecond delays if possible
	sleep_manager_lock_deep_sleep();
	Thread::wait((uint32_t)us / 1000);
	sleep_manager_unlock_deep_sleep();
	}

In other words, the 1MHz clock is enabled by wait_ms and stays on afterward.

It would be nice if wait_us was rewritten such as the us_ticker code is not invoked if the delay requested by the client code can be expressed in an integral quantity of ms or seconds.

[Mirrored to Jira]

[NeilMacMullen]

@pan Unless I'm missing something, build 5.8.x also used the 1MHz clock but didn't suffer from the excess power consumption. The code you're referencing looks like it was also present in 5.8.x. It looks like there is an attempt to force the ticker into lower power in the new code but this apparently wasn't required in 5.8.x

mbed-os/targets/TARGET_NORDIC/TARGET_NRF5x/TARGET_NRF52/sleep.c

Lines 88 to 100 in 2a824a1

	void hal_deepsleep(void)
	{
	if (us_ticker_initialized) {
	nrf_timer_task_trigger(NRF_TIMER1, NRF_TIMER_TASK_STOP);
	}
	hal_sleep();
	if (us_ticker_initialized) {
	nrf_timer_task_trigger(NRF_TIMER1, NRF_TIMER_TASK_START);
	}
	// NRF_POWER->SYSTEMOFF=1;
	}

[Mirrored to Jira]

[pan-]

@NeilMacMullen I'm just pointing out that given how wait_us is written; it makes sense that the 1MHz clock consume power continuously if your application calls wait_us forever.

That would be interesting to run a git bisect between the two revisions you indicated to find what changed codewise.
[Mirrored to Jira]

[NeilMacMullen]

@pan- Understood. It looks like the nrfx us_ticker.c code was significantly modified in commit d6b7367 - not sure it's really worth trying to bisect this given the nature of the changes but I can check whether this is what introduced the problem.
[Mirrored to Jira]

[NeilMacMullen]

Confirmed it is commit d6b7367 which introduces the extra power consumption.
The previous commit 1aebdcb is low-power.
[Mirrored to Jira]

[NeilMacMullen]

Ok - from my reading of the changes, d6b7367 appears to have switched the us_ticker implementation away from the 32kHz clock and onto the high resolution timer with a corresponding increase in power consumption. The previous implementation was called us_ticker but actually used the RTC. There is also an lp_ticker implementation but no apparent way of configuring the wait_api to use the low-power implementation rather than the high-power one. Perhaps @mprse can comment since he made the changes?
[Mirrored to Jira]

[NeilMacMullen]

It looks like the lp_ticker can be used instead of the us_ticker with the following changes. I'm not sure if this is the intended use of DEVICE_LPTICKER but it seems to do the right thing on RF52

--- a/hal/mbed_us_ticker_api.c
+++ b/hal/mbed_us_ticker_api.c
@@ -13,11 +13,18 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+
+#ifndef DEVICE_LPTICKER
 #include "hal/us_ticker_api.h"
+#else
+#include "hal/lp_ticker_api.h"
+#endif

 static ticker_event_queue_t events = { 0 };

 static ticker_irq_handler_type irq_handler = ticker_irq_handler;
+#ifndef DEVICE_LPTICKER
+

 static const ticker_interface_t us_interface = {
     .init = us_ticker_init,
@@ -28,6 +35,17 @@ static const ticker_interface_t us_interface = {
     .fire_interrupt = us_ticker_fire_interrupt,
     .get_info = us_ticker_get_info,
 };
+#else
+static const ticker_interface_t us_interface = {
+    .init = lp_ticker_init,
+    .read = lp_ticker_read,
+    .disable_interrupt = lp_ticker_disable_interrupt,
+    .clear_interrupt = lp_ticker_clear_interrupt,
+    .set_interrupt = lp_ticker_set_interrupt,
+    .fire_interrupt = lp_ticker_fire_interrupt,
+    .get_info = lp_ticker_get_info,
+};
+#endif

 static const ticker_data_t us_data = {
     .interface = &us_interface,

[Mirrored to Jira]

[NeilMacMullen]

Unfortunately my workaround appears to do nasty things to the rtc clock tracking. Here's the output of the application as it is simply running wait_ms(1000) in a loop and printing out 'time' every 60 seconds or so.... As you can see, time is rolling backwards at certain points. I need to double check but it looks like this is happening approx. every 35 minutes which just happens to be (1<<31) microseconds.

0> (34) Wed Aug 15 17:36:48 2018
0> (34) Wed Aug 15 17:37:51 2018
0> (34) Wed Aug 15 17:38:51 2018
0> (34) Wed Aug 15 17:03:13 2018
0> (34) Wed Aug 15 17:03:13 2018

[Mirrored to Jira]

[NeilMacMullen]

It seems the behaviour described above (35 minute "slippage") is not caused by my workaround since I also see it after reverting the changes. It and other issues are present on the official 5.9.4 release. See #7804
[Mirrored to Jira]

[TacoGrandeTX]

@NeilMacMullen I think the "slippage" you are observing is addressed with this PR: #7850.

[Mirrored to Jira]

[NeilMacMullen]

Thanks ralph - looking at your PR I think that's entirely consistent with what I was seeing, Unfortunately I will be on vacation for the next couple of weeks but we've managed to deploy with a combination of my LP_ticker changes above and adding the RTC feature as you suggested which appear to work well in combination. Really appreciate your help on this - I should be able to check out the "proper" fixes in a couple of weeks.
[Mirrored to Jira]

[mprse]

Sorry guys. I was out of office.

So in the previous version both us ticker and lp ticker were implemented based on RTC on NRF boards. This has been changed and now us ticker is based on 1 MHz counter. This is probably causing the extra power consumption when wait_ms() function is used. As @pan- said it will initialize high speed counter used for us ticker. To reduce the power consumption us ticker counter is stopped before entering deep-sleep mode and re-enabled after wake-up. To get the lowest power consumption the timer must be shut down (the internal core of the timer is switched off) what is not an option for us since we want to continue counting after wake up.

Please see the following part of the documentation:

The TIMER can operate in two modes, Timer mode and Counter mode. In both modes, the TIMER is started by triggering the START task, and stopped by triggering the STOP task. After the timer is stopped the timer can resume timing/counting by triggering the START task again. When timing/counting is resumed the timer will continue from the value it had prior to being stopped.
If the timer does not need to be able to resume timing/counting after a STOP, the SHUTDOWN task could be used instead of or following the STOP task.
When the timer is shut down the internal core of the timer is switched off as illustrated in Figure 38: Block schematic for timer/counter on page 229. The timer must be shut down to reach the lowest power
consumption in system ON mode. The startup time from shutdown state may be longer compared to starting the timer from the stopped state. See POWER — Power management on page 79 for more information about power modes.

I think that this is a good idea:

It would be nice if wait_us was rewritten such as the us_ticker code is not invoked if the delay requested by the client code can be expressed in an integral quantity of ms or seconds.

[Mirrored to Jira]

[TacoGrandeTX]

@NeilMacMullen Please note that our OS team is addressing this issue here #8189.

[Mirrored to Jira]

[adbridge]

Internal Jira reference: https://jira.arm.com/browse/IOTDEV-1602

[NeilMacMullen]

@mprse I'm not sure if you are suggesting that the 400uA can't be avoided at all now that the 1MHz ticker is being used or that it can be avoided (but currently isn't) when waiting for an integral number of milliseconds?

The change that claims to address this (#8189) does not seem to result in lower power in the second case. On the off-chance this is by-design rather than a bug, I'd suggest we need a configuration flag to allow a switch back to the old behaviour (using the RTC) for those people (most I expect) who would prefer low power at the expense of true microsecond accuracy.

[desmond-blue]

Hi @NeilMacMullen , since it's now a far-away Mbed OS version from the issue reported, and it seems it's already addressed, do you still need help on this issue? Thanks.

[NeilMacMullen]

no - I think this one can be closed.