Closed
Description
I don't know if this is by (unfortunate) design or not, but time.monotonic() slows down under pressure.
I run a script to measure RTC accuracy and it slows down the monotonic clock.
This snippet is run on the board through the REPL to give me the moment that the second ticks over:
import time
lt1 = time.localtime()
lt2 = lt1
i = 0
while lt1.tm_sec == lt2.tm_sec:
lt2 = time.localtime()
i += 1
m = time.monotonic()
print("%%s:%%.6f:%%d" %% ( str(tuple(lt2)), m, i ))This is the resulting test script output:
-0.005966 secs / 0.000025 days = -238.187512 secs/day (-2756.80 ppm) : 27 May 2018 22:38:30 (2286.009 - 2285.562 = 0.447) : 127
-0.001031 secs / 0.000037 days = -28.206318 secs/day (-326.46 ppm) : 27 May 2018 22:38:31 (2286.456 - 2286.009 = 0.447) : 124
The important part is the last two numbers: monotonic has elapsed ~0.5 seconds and the loop has run 127/124 times.
If I add a 100ms delay in the loop:
import time
lt1 = time.localtime()
lt2 = lt1
i = 0
while lt1.tm_sec == lt2.tm_sec:
lt2 = time.localtime()
i += 1
time.sleep(0.1)
m = time.monotonic()
print("%%s:%%.6f:%%d" %% ( str(tuple(lt2)), m, i ))Then I get that monotonic has elapsed ~1 second and the loop has run 7/8 times:
+0.055680 secs / 0.000026 days = +2114.643333 secs/day (+24475.04 ppm) : 27 May 2018 22:40:08 (2366.929 - 2366.016 = 0.913) : 7
+0.010000 secs / 0.000038 days = +260.184927 secs/day (+3011.40 ppm) : 27 May 2018 22:40:09 (2367.941 - 2366.929 = 1.013) : 8
-0.025755 secs / 0.000050 days = -510.800835 secs/day (-5912.05 ppm) : 27 May 2018 22:40:10 (2368.938 - 2367.941 = 0.997) : 8
+0.029896 secs / 0.000061 days = +487.286023 secs/day (+5639.88 ppm) : 27 May 2018 22:40:11 (2369.850 - 2368.938 = 0.911) : 7
-0.026185 secs / 0.000074 days = -355.902557 secs/day (-4119.24 ppm) : 27 May 2018 22:40:12 (2370.868 - 2369.850 = 1.019) : 8
This is with a 10ms sleep:
+0.006152 secs / 0.000025 days = +243.827366 secs/day (+2822.08 ppm) : 27 May 2018 22:56:36 (3344.759 - 3343.982 = 0.777) : 54
+0.001943 secs / 0.000037 days = +52.725427 secs/day (+610.25 ppm) : 27 May 2018 22:56:37 (3345.534 - 3344.759 = 0.775) : 55
+0.007818 secs / 0.000048 days = +161.654050 secs/day (+1871.00 ppm) : 27 May 2018 22:56:38 (3346.313 - 3345.534 = 0.779) : 53
Does anyone have an explanation for this?