time.monotonic_ns is not always monotonic on 5.3.1

[kevinjwalters]

Assuming the order is well defined for evaluation of list elements something odd is going on here as monotonic_ns() is briefly jumping backwards:

Adafruit CircuitPython 5.3.1 on 2020-07-13; Adafruit CLUE nRF52840 Express with nRF52840
>>> import time
>>> good = not_as_good = 0
>>> while True:
...     t_t = [time.monotonic_ns(), time.monotonic_ns(), time.monotonic_ns(), time.monotonic_ns()]
...     if sorted(t_t) != t_t:
...         not_as_good += 1
...         print("OH NO", not_as_good, good, t_t)
...     else:
...         good += 1
...
...
...
OH NO 1 250 [16599889931000, 16599889967000, 16599889004000, 16599890039000]
OH NO 2 410 [16600212931000, 16600212966000, 16600212004000, 16600213038000]
OH NO 3 431 [16600492896000, 16600492932000, 16600492966000, 16600492004000]
OH NO 4 458 [16600502966000, 16600502004000, 16600503039000, 16600503074000]
OH NO 5 590 [16600817966000, 16600817003000, 16600818039000, 16600818073000]
OH NO 6 743 [16601144895000, 16601144931000, 16601144966000, 16601144003000]
OH NO 7 834 [16601445931000, 16601445966000, 16601445004000, 16601446039000]
OH NO 8 940 [16601751895000, 16601751931000, 16601751966000, 16601751004000]
OH NO 9 1051 [16602059931000, 16602059967000, 16602059004000, 16602060039000]
OH NO 10 1187 [16602375896000, 16602375931000, 16602375967000, 16602375003000]

Taking numbers from 4th line of output and adding a space shows this is possibly an issue as the ms portion increments, second line looks like it should be 16600503004000:

16600502 966000
16600502 004000
16600503 039000
16600503 074000

[tannewt]

Seems like a concurrency issue when reading the underlying timer(s).

[kevinjwalters]

I had a PyPortal (SAMD51) plugged in and thought it was worth a test to check behaviour there. I'll leave it running for an hour but it looks good so far as there's been no output after 5 mins.

Adafruit CircuitPython 5.3.1 on 2020-07-13; Adafruit PyPortal with samd51j20
>>> import time
>>> good = not_as_good = 0
>>> while True:
...     t_t = [time.monotonic_ns(), time.monotonic_ns(), time.monotonic_ns(), time.monotonic_ns()]
...     if sorted(t_t) != t_t:
...         not_as_good += 1
...         print("OH NO", not_as_good, good, t_t)
...     else:
...         good += 1
...
...
...

[kevinjwalters]

Seems like a concurrency issue when reading the underlying timer(s).

The values read would be binary but the problem appears (based on a small sample) on a decimal boundary. This is odd. Is there a "sub timer" used for sub ms part?

[tannewt]

It doesn't look like it: https://github.com/adafruit/circuitpython/blob/main/ports/nrf/supervisor/port.c#L275

[DavePutz]

I tested this with a Clue as well. On 5.3.1 the error reproduced immediately, on 6.0.0-beta.0 it ran without error for 10 minutes. It looks like there were significant changes in how time.monotonic_ns is calculated on the nrf52840 port between the two versions.

[tannewt]

@DavePutz Totally, the sleep work I did switched our internal timekeeping to the real time clock on all ports.

@kevinjwalters I'm closing this because it is fixed for 6.x.

[kevinjwalters]

There's something afoot with port_get_raw_ticks() underneath monotonic_ns() for STM32F405 boards in #3376 which sounds like this.

Perhaps this should go in whatever test suite there is to detect and prevent this from reoccuring?