RF52 serious behavioural regressions in RTC

[NeilMacMullen]

GCC_ARM
nRF52 platform.
mbed-os-5.9.4

See #7763 for the likely breaking change.

The following code demonstrates that the seconds and minutes are NOT being correctly reset when calling set_time.

Further, other strange behaviour includes that described in #7763 where setting the clock (backwards?) can sometimes cause it to 'pause' for 35 minutes (1<<31 us).

I'm pretty sure I've also seen the clock drift significantly (several minutes over the course of an hour).

#include "mbed.h"

#include "segger_rtt.h"

int main()
{
    for (int hour = 23; hour >= 0; hour--)
    {
        for (int z = 0; z < 12; z++)
        {
            SEGGER_RTT_printf(0, "resetting time using hour %d...\n", hour);

            struct tm t
            {
            };
            t.tm_year = 2018 - 1900;
            t.tm_mon = 8 - 1;
            t.tm_mday = 16;
            t.tm_hour = hour;
            t.tm_min = 1;
            t.tm_sec = 1;
            set_time(mktime(&t));

            for (int c = 0; c < 10; c++)
            {
                time_t seconds = time(NULL);
                SEGGER_RTT_printf(0, "%s", ctime(&seconds));
                wait_ms(1000);
            }
        }
    }
    return 0;
}

Here's typical output. Note that the seconds/minutes are not being reset but hours are. I've confirmed the behaviour is correct on 5.8.5

0> resetting time using hour 23...
0> Thu Aug 16 23:02:41 2018
0> Thu Aug 16 23:02:41 2018
0> Thu Aug 16 23:02:42 2018
0> Thu Aug 16 23:02:43 2018
0> Thu Aug 16 23:02:44 2018
0> Thu Aug 16 23:02:45 2018
0> Thu Aug 16 23:02:46 2018
0> Thu Aug 16 23:02:47 2018
0> Thu Aug 16 23:02:48 2018
0> Thu Aug 16 23:02:49 2018
0> resetting time using hour 23...
0> Thu Aug 16 23:02:51 2018
0> Thu Aug 16 23:02:51 2018
0> Thu Aug 16 23:02:52 2018
0> Thu Aug 16 23:02:53 2018
0> Thu Aug 16 23:02:54 2018
0> Thu Aug 16 23:02:55 2018
0> Thu Aug 16 23:02:56 2018
0> Thu Aug 16 23:02:57 2018
0> Thu Aug 16 23:02:58 2018
0> Thu Aug 16 23:02:59 2018
0> resetting time using hour 22...
0> Thu Aug 16 22:03:01 2018
0> Thu Aug 16 22:03:01 2018
0> Thu Aug 16 22:03:02 2018
0> Thu Aug 16 22:03:03 2018
0> Thu Aug 16 22:03:04 2018
0> Thu Aug 16 22:03:05 2018
0> Thu Aug 16 22:03:06 2018
0> Thu Aug 16 22:03:07 2018
0> Thu Aug 16 22:03:08 2018
0> Thu Aug 16 22:03:09 2018
0> resetting time using hour 22...
0> Thu Aug 16 22:03:11 2018
0> Thu Aug 16 22:03:11 2018
0> Thu Aug 16 22:03:12 2018
0> Thu Aug 16 22:03:13 2018
0> Thu Aug 16 22:03:14 2018
0> Thu Aug 16 22:03:15 2018
0> Thu Aug 16 22:03:16 2018
0> Thu Aug 16 22:03:17 2018
0> Thu Aug 16 22:03:18 2018
0> Thu Aug 16 22:03:19 2018

[NeilMacMullen]

@MarceloSalazar @pan- @mprse
[Mirrored to Jira]

[NeilMacMullen]

set_time seems to have been broken between 5.8.6 ( expected behaviour) and 5.9.0 (incorrect)
[Mirrored to Jira]

[NeilMacMullen]

For good measure I verified it is also broken on 5.9.5
[Mirrored to Jira]

[TacoGrandeTX]

@NeilMacMullen We're still root-causing this issue, but a work-around to the problem with set_time() is to re-introduce the "RTC" property to the "Device Has" list in targets.json for the MCU_NRF52832. We see that working properly with your test code. However, it's not clear what other ramifications that will have on your end app.

[Mirrored to Jira]

[NeilMacMullen]

Thanks @TacoGrandeTX I'll do some testing with this today and let you know of any relevant findings.
[Mirrored to Jira]

[NeilMacMullen]

On the basis of some light testing, this does look to have fixed the issues I was seeing and even works with the low-power workaround I describe in #7763. Thanks!
[Mirrored to Jira]

[TacoGrandeTX]

@NeilMacMullen Thanks for the report - that's good to hear. Even without DEVICE_RTC we are still using RTC1 (running at 32kHz) for updating our internal ticker for time-keeping. Our internal rtc_lp_base is being set appropriately by set_time() but we might be mishandling the internal ticker. We will have more for you early next week.

[Mirrored to Jira]

[NeilMacMullen]

It seems I spoke too soon :( Although I haven't managed to find a simple repro case, the esp8266-driver is now failing consistently (after RTC added to targets.json). It looks like the Timer implementation is not returning sensible values for read_ms but I haven't yet been able to verify directly.
[Mirrored to Jira]

[NeilMacMullen]

Further to the above comment..... The difference in behaviour actually occurs when there are two threads in the system, a producer 'A' and a consumer 'B' .

A is running a tight loop using wait_ms(1) to interject some idle time between checks of a peripheral.
B is busy-waiting in a while(1) loop (checking a status flag set by B.

In this scenario, when the RTC feature is added, thread A stalls on the wait_ms(1) presumably because the scheduler is not pre-empting B at all. As evidence for this, as soon as B abandons its loop, the A loop resumes.

Adding a small wait inside the B loop allows the code to work correctly (as does reverting the RTC feature).

Clearly, a better design would be for the code in B to use waits but it's interesting the behaviour changes as RTC is added/removed.

FYI, the B code is the get/putc code in https://os.mbed.com/teams/ESP8266/code/esp8266-driver/file/6946b0b9e323/ESP8266/ATParser/ATParser.cpp/
[Mirrored to Jira]

[TacoGrandeTX]

@NeilMacMullen I'm testing a fix that is looking good. The timer used to keep track of usec was not being reset on set_time():

void set_time(time_t t)
{
    _mutex->lock();
    if (_rtc_init != NULL) {
        _rtc_init();
    }
    if (_rtc_write != NULL) {
        _rtc_write(t);
        _rtc_lp_timer->reset();
    }
    _mutex->unlock();
}

Will update again ASAP (hopefully with a pull request).
[Mirrored to Jira]