STM: Incorrect us ticker timestamp after deep sleep

[fkjagodzinski]

Description

After waking up from deep sleep mode the ticker_read_us(us_ticker) returns incorrect value. In fact that value is 2**32-1 or 2*33-1 bigger than expected.

Targets

NUCLEO_F746ZG,
NUCLEO_L476RG,
NUCLEO_F401RE,
NUCLEO_F429ZI,
DISCO_L475VG_IOT01A

Toolchains

GCC_ARM
I don't suspect this issue to be toolchain related. I'll update this list whenever I check other toolchain builds.

Mbed OS SHA

8d9e2e5 -- master

Code

#include "mbed.h"

#define NO_OS_INTERFERENCE 0

#if NO_OS_INTERFERENCE
#include "mbed_lp_ticker_wrapper.h"
#endif

#define SLEEP_DURATION_US 100000ULL
#define SERIAL_FLUSH_TIME_MS 20

void wakeup_callback(volatile int *wakeup_flag)
{
    (*wakeup_flag)++;
}

int main()
{
#if NO_OS_INTERFERENCE
    // Suspend the RTOS kernel scheduler to prevent interference with duration of sleep.
    osKernelSuspend();
#if DEVICE_LPTICKER && (LPTICKER_DELAY_TICKS > 0)
    // Suspend the low power ticker wrapper to prevent interference with deep sleep lock.
    lp_ticker_wrapper_suspend();
#endif
#endif

    volatile int wakeup_flag;
    LowPowerTimeout lp_timeout;
    const ticker_data_t *const us_ticker = get_us_ticker_data();
    const ticker_data_t *const lp_ticker = get_lp_ticker_data();

    uint32_t us_ticks1, us_ticks2, lp_ticks1, lp_ticks2;
    us_timestamp_t us_ts1, lp_ts1, us_ts2, lp_ts2;

    MBED_ASSERT(sleep_manager_can_deep_sleep());

    // Wait for hardware serial buffers to flush.
    wait_ms(SERIAL_FLUSH_TIME_MS);

    wakeup_flag = 0;
    lp_timeout.attach_us(mbed::callback(wakeup_callback, &wakeup_flag), SLEEP_DURATION_US);

    us_ticks1 = us_ticker_read();
    lp_ticks1 = lp_ticker_read();
    us_ts1 = ticker_read_us(us_ticker);
    lp_ts1 = ticker_read_us(lp_ticker);

    // Deep sleep unlocked -- deep sleep mode used:
    // * us_ticker powered OFF,
    // * lp_ticker powered ON.
    while (wakeup_flag == 0) {
        sleep_manager_sleep_auto();
    }

    us_ticks2 = us_ticker_read();
    lp_ticks2 = lp_ticker_read();
    us_ts2 = ticker_read_us(us_ticker);
    lp_ts2 = ticker_read_us(lp_ticker);

    printf("------------------------------------------------------------\r\n");
    printf("%24s%12s%12s%12s\r\n", "us_ticks", "us_ts", "lp_ticks", "lp_ts");
    printf("%12s%12lu%12llu%12lu%12llu\r\n", "before", us_ticks1, us_ts1, lp_ticks1, lp_ts1);
    printf("%12s%12lu%12llu%12lu%12llu\r\n", "after", us_ticks2, us_ts2, lp_ticks2, lp_ts2);
    printf("%12s%12lu%12llu%12lu%12llu\r\n", "diff", us_ticks2 - us_ticks1, us_ts2 - us_ts1, lp_ticks2 - lp_ticks1,
           lp_ts2 - lp_ts1);
    printf("\r\n");
    wait_ms(SERIAL_FLUSH_TIME_MS);
}

Output

NUCLEO_F746ZG:

------------------------------------------------------------
                us_ticks       us_ts    lp_ticks       lp_ts
      before       20288       20258         655       19989
       after       20304  4294987570        3964      121002
        diff          16  4294967312        3309      101013

NUCLEO_L476RG:

------------------------------------------------------------
                us_ticks       us_ts    lp_ticks       lp_ts
      before       20387       20313         656       20050
       after       20435  8589954954        4031      123016
        diff          48  8589934641        3375      102966

NUCLEO_F429ZI:

------------------------------------------------------------
                us_ticks       us_ts    lp_ticks       lp_ts
      before       20208       20176       98467       20019
       after       20277  4294987541       99297      121337
        diff          69  4294967365         830      101318

Issue request type

[ ] Question
[ ] Enhancement
[X] Bug

[fkjagodzinski]

I might have found the cause of this issue. update_present_time(us_ticker) is called a few times while the hal_deepsleep() hasn't finished its execution yet. This can be seen on the screenshot below. I used GPIOs to track function calls (code: https://github.com/fkjagodzinski/mbed-os/commits/dbg-stm-us_ticker_after_deepsleep).

After waking up from deep sleep mode, the context of us ticker is restored.

mbed-os/targets/TARGET_STM/sleep.c

Line 215 in d6ccf46

restore_timer_ctx();

This happens inside hal_deepsleep(), but there is still some code that calls ticker_read_us(us_ticker) before that.

Calling update_present_time() when the us ticker counter register value is very low results in storing an incorrect value in us_ticker->queue->tick_last_read, which in turn breaks all following calls to ticker_read_us(us_ticker).

mbed-os/hal/mbed_ticker_api.c

Line 138 in d6ccf46

queue->tick_last_read = ticker_time;

[fkjagodzinski]

The root cause of this issue is HAL_GetTick() calling ticker_read_us(us_ticker).

mbed-os/targets/TARGET_STM/hal_tick_overrides.c

Lines 45 to 69 in d6ccf46

	uint32_t HAL_GetTick()
	{
	#if TIM_MST_BIT_WIDTH == 16
	uint32_t new_time;
	if (mbed_sdk_inited) {
	// Apply the latest time recorded just before the sdk is inited
	new_time = ticker_read_us(get_us_ticker_data()) + prev_time;
	prev_time = 0; // Use this time only once
	return (new_time / 1000);
	}
	else {
	new_time = us_ticker_read();
	elapsed_time += (new_time - prev_time) & 0xFFFF; // Only use the lower 16 bits
	prev_time = new_time;
	return (elapsed_time / 1000);
	}
	#else // 32-bit timer
	if (mbed_sdk_inited) {
	return (ticker_read_us(get_us_ticker_data()) / 1000);
	}
	else {
	return (us_ticker_read() / 1000);
	}
	#endif
	}

One of possible fixes would be to update the value of the mbed_sdk_inited flag in hal_deepsleep(), i.e.:

diff --git a/targets/TARGET_STM/sleep.c b/targets/TARGET_STM/sleep.c
index 50759eb..a6e01e6 100644
--- a/targets/TARGET_STM/sleep.c
+++ b/targets/TARGET_STM/sleep.c
@@ -158,6 +158,7 @@ void hal_sleep(void)
 }
 
 extern int serial_is_tx_ongoing(void);
+extern int mbed_sdk_inited;
 
 void hal_deepsleep(void)
 {
@@ -199,6 +200,7 @@ void hal_deepsleep(void)
 #else /* TARGET_STM32L4 */
     HAL_PWR_EnterSTOPMode(PWR_LOWPOWERREGULATOR_ON, PWR_STOPENTRY_WFI);
 #endif /* TARGET_STM32L4 */
+    mbed_sdk_inited = 0;
 
     // Verify Clock Out of Deep Sleep
     ForceClockOutofDeepSleep();
@@ -213,6 +215,7 @@ void hal_deepsleep(void)
     wait_loop(500);
 
     restore_timer_ctx();
+    mbed_sdk_inited = 1;
 
     // Enable IRQs
     core_util_critical_section_exit();

With this patch added, the output from NUCLEO_F746ZG is ok:

------------------------------------------------------------
                us_ticks       us_ts    lp_ticks       lp_ts
      before       20288       20258         655       19989
       after       20305       20275        3962      120910
        diff          17          17        3307      100921

This might not be the best solution though. @ARMmbed/team-st-mcd, @c1728p9 @0xc0170 could you take a look?

[jeromecoutant]

It is OK for me, thx @fkjagodzinski

Please, push the correction, I will check it with many STM32 targets.

[ciarmcom]

ARM Internal Ref: MBOTRIAGE-1652

[fkjagodzinski]

@jeromecoutant I created PR with a patch I proposed above.