Mbed-os: [OOB-5.14] Cannot get DISCO_L475VG_IOT01A or NUCLEO_F411RE to deep sleep.

[korjaa]

Description

Targets: DISCO_L475VG_IOT01A and NUCLEO_F411RE
Toolchain: GCC_ARM 6.3.1 20170620 (release)
mbed-cli: 1.10.0
mbed-os: f60e9a8075 (HEAD, tag: mbed-os-5.14.0-rc2, origin/mbed-os-5.14) Merge pull request #11476 from ARMmbed/release-candidate

Steps to reproduce:

1. Create new project with mbed new
2. Checkout mbed-os-5.14.0-rc2
3. Add below to mbed_app.json (https://os.mbed.com/docs/mbed-os/development/tutorials/power-optimization.html)

{
    "target_overrides": {
        "*": {
             "platform.cpu-stats-enabled": 1,
             "platform.stdio-buffered-serial": false,
             "platform.stdio-convert-newlines": true,
             "rtos.idle-thread-stack-size": 4096,
             "rtos.idle-thread-stack-size-debug-extra": 4096
        }
    },
    "macros": ["MBED_TICKLESS=1", "MBED_CONF_TARGET_TICKLESS_FROM_US_TICKER=0"]
}

1. Add below to main.cpp

#include "mbed.h"
#include "mbed_stats.h"

static DigitalOut led(LED1);

static int dummy = printf("Hello\n");

int main() {
   printf("Start example\n");
   fflush(stdout);
   wait_ms(2000);
   while (1) {
       led = !led;
       wait_ms(2000);

       mbed_stats_cpu_t stats;
       mbed_stats_cpu_get(&stats);
       printf("Uptime: %llu ", stats.uptime / 1000);
       printf("Sleep time: %llu ", stats.sleep_time / 1000);
       printf("Deep Sleep: %llu\n", stats.deep_sleep_time / 1000);
   }
}

1. Compile mbed compile --target DISCO_L475VG_IOT01A --flash & test
2. Compile mbed compile --target NUCLEO_F411RE --flash & test
3. Monitor deep sleep numbers

Log output:

Hello
Start example
Uptime: 4022 Sleep time: 3999 Deep Sleep: 0
Uptime: 6066 Sleep time: 5998 Deep Sleep: 0
Uptime: 8110 Sleep time: 7997 Deep Sleep: 0
Uptime: 10154 Sleep time: 9996 Deep Sleep: 0
Uptime: 12200 Sleep time: 11996 Deep Sleep: 0
Uptime: 14247 Sleep time: 13996 Deep Sleep: 0

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug

[bulislaw]

Did that ever work? You are printing using serial so maybe it blocks the deep sleep? Worth dumping the sleep locks, info can be found on the page you referenced. Also the changes and macros you added shouldn't be necessary.

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-1779

[evedon]

Some work is being done to implement suspend for UART peripherals ; at the moment, UART peripheral will prevent device from entering deep sleep.

[LMESTM]

@evedon can you be more explicit ? Since when does UART peripheral / printf usage prevent deep_sleep entry.
I remember to have this tested okay few (or months?) weeks ... well not so long ago.

[evedon]

The information is on the page referenced https://os.mbed.com/docs/mbed-os/development/tutorials/power-optimization.html

Every class that inherits from SerialBase, such as Serial, if it has a receive interrupt attached. Additionally, deep sleep is blocked temporarily while using the asynchronous APIs for reading and writing.

If you say that this was working not so long ago, then the page should probably be updated with a list of targets for which this works.

[LMESTM]

I'm ending up in a "page not found" ... but from your copy/paste:

• I don't think we have an attached interrupt here
• I don't think either that Async read or write is ongoing
  so this should not be what is blocking us here ...

[LMESTM]

Unfortunately tracing sleep locks seems impossible on master (tracked here #11497 )

But I used a debugger and a modified version of mbed-os where sleep locks are being traced in ram but there is no output to Serial. It shows that SysTimer.cpp is preventing from entering deep sleep:
$2 = {{identifier = "lp_ticker.c\000\000\000", count = 0 '\000'}, {identifier = "SysTimer.cpp\000\000", count = 1 '\001'}, {identifier = '\000' <repeats 14 times>, count = 0 '\000'}, { identifier = '\000' <repeats 14 times>, count = 0 '\000'}, {identifier = '\000' <repeats 14 times>, count = 0 '\000'}, {identifier = '\000' <repeats 14 times>, count = 0 '\000'}, { identifier = '\000' <repeats 14 times>, count = 0 '\000'}, {identifier = '\000' <repeats 14 times>, count = 0 '\000'}, {identifier = '\000' <repeats 14 times>, count = 0 '\000'}, { identifier = '\000' <repeats 14 times>, count = 0 '\000'}}
@kjbracey-arm you seem to have looked in the past to the locking from SysTimer - any idea under what condition SysTimer will prevent the deep sleep ?

[korjaa]

Not sure if related, but someone recommended me to disable stdin. So just recording it here that the below didn't help

Added to main.cpp:

printf("Disabling stdin\n");
mbed_file_handle(STDIN_FILENO)->enable_input(false);
mbed_file_handle(STDIN_FILENO)->enable_output(false);

Log output:

Start example
Disabling stdin
Uptime: 4039 Sleep time: 3999 Deep Sleep: 0
Uptime: 6083 Sleep time: 5997 Deep Sleep: 0
Uptime: 8127 Sleep time: 7996 Deep Sleep: 0
Uptime: 10171 Sleep time: 9995 Deep Sleep: 0
Uptime: 12217 Sleep time: 11995 Deep Sleep: 0
Uptime: 14264 Sleep time: 13995 Deep Sleep: 0

[LMESTM]

@kjbracey-arm
Some more information:
removing this Sys Timer lock here allows to enter deep sleep just fine

================= CPU STATS =================
Idle: 100% Usage: 0%
Sleep: 0%, Deep_sleep: 100%

I'm not sure, but here what I think I'm observing:
1) At the time of [this condition] (https://github.com/ARMmbed/mbed-os/blob/master/platform/source/SysTimer.cpp#L121) is evaluated, the lp_ticker driver from STM32 has a lock - basically we need this lock for the next 100µs or so to make sure HW programming in complete. So SysTimer is also taking the lock to avoid race condition as mentioned in the comment..
2) few 100µs or so later, the lp_ticker lock is released, but that doesn't trigger any new SysTimer activity. The next activity is already programmed and won't be programmed again, so the SysTimer lock is kept until 5 seconds later (next blinky) ...

[LMESTM]

@MarceloSalazar This issue should be fixed in 5.14.
I've proposed a change in #11522 but that needs to be reviewed and verified by mbed-os experts.

One extra question : isn't there a automated test in CI, very simple and similar to blinky that verifies that deep sleep is entered fine ?

[korjaa]

@LMESTM I did the modification that you mentioned #11522 and I can confirm that it does enable the deep sleep. Though I'm not getting identical numbers, my code seems to spend some time in regular sleep also

Uptime: 3591312 Sleep time: 3631 Deep Sleep: 3492744
Uptime: 3593366 Sleep time: 3634 Deep Sleep: 3494740
Uptime: 3595421 Sleep time: 3636 Deep Sleep: 3496738

I'm not familiar with Mbed OS testing, maybe @jamesbeyond or @OPpuolitaival can clarify.

[LMESTM]

@LMESTM I did the modification that you mentioned #11522 and I can confirm that it does enable the deep sleep. Though I'm not getting identical numbers, my code seems to spend some time in regular sleep also

Sounds good. I'm not sure why I got 100% during first test, should be less. I rather have 99% now. I'm not using your exact code. The actual values depends on target, wait loop period (I'm using 5sec), serial port com speed (I used 115200), ....

[korjaa]

I can verify that deep sleep works now with mbed-os-5.14.0-rc3. The issue was fixed with #11522.