Slow time on micro:bit V1 and V2

[kevinjwalters]

I've observed that time is slow in micropython on the micro:bit V1 and V2 using v1.18 from https://python.microbit.org/v/3

This program using sleep runs for longer than 100 seconds.

from microbit import sleep

sleep(15 * 1000)
pause_ms = 100 * 1000

count = 1
while True:
    print("{:06d}".format(count))
    sleep(pause_ms)
    count += 1

It produces this output (borrowed the Arduino IDE as it has timestamping, running on Windows 11)

20:44:16.077 -> 000001
20:45:56.757 -> 000002
20:47:37.501 -> 000003
20:49:18.167 -> 000004
20:50:58.920 -> 000005
20:52:39.635 -> 000006
20:54:20.306 -> 000007

On v1.18

KeyboardInterrupt:
MicroPython v1.18 on 2023-10-30; micro:bit v2.1.2 with nRF52833
Type "help()" for more information.

The 100 second sleep (plus a tiny bit of processing for format/print/increment) is 100.680, 100.744, 100.666, 100.753, 100.715, 100.671. The clock appears to be running about 0.7% slow (at 23C). It's easy to dismiss this as poor time keeping on a microcontroller but the micro:bit V2 has a crystal (listed in BOM) and all is fine in CircuitPython on same board.

I first noticed this when checking the performance of the MCP7940N rtc on a ZIP Halo HD vs MicroPython utime.ticks_us(). Across 24 hours the RTC is running about 18 seconds fast (I think this has a trim feature which I may explore to get it spot on), MicroPython is 552 seconds slow (about 0.64%) and CircuitPython (time.monotonic_ns()) is just 2 seconds slow (extrapolated, I only had time to run the test for ~90 mins).

@JackAtKitronik might be interested in this.

[kevinjwalters]

I wasn't expecting this but just tried on a V1 and same thing.

21:17:05.310 -> 000001
21:18:45.989 -> 000002
21:20:26.738 -> 000003
21:22:07.441 -> 000004
21:23:48.167 -> 000005
21:25:28.859 -> 000006
21:27:09.597 -> 000007

That's 100.679, 100.749, 100.703, 100.726, 100.692, 100.738 seconds.

[kevinjwalters]

For comparison, MakeCode on V2:

13:39:20.760 -> 000001
13:41:00.739 -> 000002
13:42:40.758 -> 000003
13:44:20.778 -> 000004
13:46:00.817 -> 000005
13:47:40.861 -> 000006
13:49:20.870 -> 000007

That's 99.979, 100.019, 100.020, 100.039, 100.044, 100.009 seconds.

[microbit-carlos]

That's really interesting, thanks for the report @kevinjwalters.

I believe the internal RC clock might be used unless BLE or radio is running. Could you turn on the radio and test again to see if that makes a difference?

[kevinjwalters]

My V2 is busy at the moment testing a trimmed MCP7940N. The same V1 is still slow with this code

from microbit import sleep
import radio

radio.config(group=23)
radio.on()

sleep(15 * 1000)
pause_ms = 100 * 1000

count = 1
while True:
    print("{:06d}".format(count))
    sleep(pause_ms)
    count += 1

produces

15:00:50.008 -> 000001
15:02:30.700 -> 000002
15:04:11.390 -> 000003
15:05:52.107 -> 000004
15:07:32.838 -> 000005

on MicroPython v1.9.234-gd64154c73 on 2017-09-01; micro:bit v1.1.1 with nRF51822.

[kevinjwalters]

From my first tests on V2 I have a linear corrected version of graph and that does show MicroPython is all over the place which supports the explanation of a mediocre internal oscillator.

[kevinjwalters]

I think this was discovered back in 2016 too on the V1 in REUK.co.uk: Testing Accuracy of micro:bit Internal Clock, that one was out by (600/598.51 -1) * 1000 * 1000 = +2489.5ppm

[martinwork]

An alternative method to monitor micro:bit's time: millis.zip

Install millis-python.hex in micro:bit V2. Run millis.py on PC. The PC periodically asks micro:bit for it's millis clock and compares it's elapsed time. Disconnect WebUSB or it will corrupt the python serial.

It's clear within a minute that the micro:bit V2 is not quite 1% out.

Edit millis-python.hex to #import radio, and test again. Radio enables the HFCLK in V2, and the micro:bit times seem to match the PC to the millisecond, though I haven't run the test for more than a few minutes,

I think micropython is using a version of CODAL before the HFCLK was always enabled:

https://github.com/lancaster-university/codal-microbit-v2/blob/d159aba47e1797ace83ffbac81009909326f3c4f/model/MicroBit.cpp#L291

lancaster-university/codal-microbit-v2@ed14fa2

[microbit-carlos]

Thanks Martin! I had forgotten newer CODAL releases had enabled the crystal on uBit.init().

@kevinjwalters if you try any of the MicroPython builds from this CI job, it should use the crystal by default and provide more accurate timings (so the next MicroPython release will have this by default as well):
https://github.com/microbit-carlos/micropython-microbit-v2/actions/runs/14669538988

[kevinjwalters]

@microbit-carlos I have tried a recent v1.23.0 build which @martinwork made. When my code in Arduino IDE (for timestamping) it looked much improved. BUT there's a curious anomaly between two of my micro:bit. By luck I had some code that times some maths and it takes a different about of time on this version between two micro:bits. 456ms is what I'd expect, 481ms is strangely slow, times below in us.

ZHH-B
R24 MATH 481399
 
ZHH-D
R24 MATH 455705

The full output is in lancaster-university/codal-microbit-v2#475 (comment)