time.sleep waits less than expected

[ishahak]

CircuitPython version

Adafruit CircuitPython 8.1.0-beta.1-48-g98a1083d6-dirty on 2023-08-22; ESP32-S3-DevKitC-1-N32R8 with ESP32S3

Code/REPL

import time

LOOP=200
acc = 0
for i in range(LOOP):
    t = time.monotonic_ns()
    time.sleep(0.01)
    t2 = time.monotonic_ns()
    diff_us = (t2-t) // 1000
    acc += diff_us
avg = acc / LOOP
print(f'expected 10000 us, got {avg} us')

Behavior

The result shows: expected 10000 us, got 9799.07 us

Description

see: https://forums.adafruit.com/viewtopic.php?p=1024856#p1024856

Additional information

No response

[todbot]

You should try that on CircuitPython 9.1 or better. There have been many updates to the ESP32 internals since 8.1.

[anecdata]

Similar in 9.1.4. A sliver of the loss (<8us) is from the time it takes to call time.monotonic_ns() (time.sleep() takes a little longer). There also seems to be a tinier sliver lost to the float division and the accumulation of truncation errors. Without any division::

expected = 2_000_000_000 ns
actual   = 1_961_395_269 ns (avg 9806.98 us)

But the point remains that time.sleep() doesn't match time.monotonic_ns().

Similar results on Pico [W]:

expected 10000 us, got 9867.55 us
(total: 1_973_510_795 ns; total attributable to time.monotonic_ns() call: 4_211_402 ns)

[ishahak]

Re @todbot, if you followed the linked forum discussion you'll see that bug was reproduced on 9.1.1 as well

[todbot]

Right, thanks I see that now. Also, thanks @anecdata. In my experience trying to do tight-timing on CircuitPython this isn't very surprising. CircuitPython has no concept of atomic or critical sections so who knows what happens during those three function calls: USB handling and garbage collection come to mind as tasks that eat up several milliseconds.

Perhaps a similar test that was disconnected from USB, does a gc.disable() before starting, and then logs the final results to a file would give you a better indication as to true timing. That's not very satisfactory, but I've not found a way for CircuitPython to not be 5-10 milliseconds sloppy with timing. That you're only getting 0.2 milliseconds variation is pretty great, to me.

[dhalbert]

What I think is odd here is that the time is less that the requested time. I'd expect overhead to make it longer. So I'm suspecting a ticks-vs-msec issue: a tick is 1/1024 of a second vs the msec 1/1000 of a second. It could be an error in converting ticks to msecs or assuming one is the other.

[todbot]

Oh yes, under the requested value. You are correct. I need more coffee.

[johnnohj]

I think adafruit_support_bill got it right way back in August: here. Plus, any short sleep will be accentuated by the floored division diff_us = (t2-t) // 1000 which rounds decimal remainders down to the nearest integer, e.g., 1.999999 -> 1 (per the docs). See also this for a detailed discussion of what adafruit_support_bill and @dhalbert describe. (Of interest might be the point made about perhaps seeing greater accuracy, in this case, with time.sleep(0.1) instead)

[todbot]

I think adafruit_support_bill got it right way back in August: here. Plus, any short sleep will be accentuated by the floored division [...]

Ah yes, I have experienced this. In #9237 I was convinced it was a problem with floats in CircuitPython because 0.004 seconds * 1000 millis/sec != 4 milliseconds.

[johnnohj]

Ah yes, I have experienced this. In #9237 I was convinced it was a problem with floats in CircuitPython because 0.004 seconds / 1000 != 4 milliseconds.

My favorite quote from the discussion:

"Note that this is in the very nature of binary floating point: this is not a bug in Python, and it is not a bug in your code either. You’ll see the same kind of thing in all languages that support your hardware’s floating-point arithmetic" (emphasis mine)

[dhalbert]

Plus, any short sleep will be accentuated by the floored division diff_us = (t2-t) // 1000 which rounds decimal remainders down to the nearest integer, e.g., 1.999999 -> 1 (per the docs).

I think this is still something to follow up on. We might round instead of truncating. And I am still suspicious of 1024 vs 1000. 9.7 vs 10 is not a few least-significant bits of difference.

[johnnohj]

I think this is still something to follow up on. We might round instead of truncating. And I am still suspicious of 1024 vs 1000. 9.7 vs 10 is not a few least-significant bits of difference.

I had played around with altering the value given time.sleep; the handful of substitute values tried were enough to suggest that expressions are perhaps being evaluated according to The Price is Right rules, which is to say what it returns is as near as possible the specified value without going over, within the limits of floating point/ (1000/1024) math.

Using values for sleep from 0.08 to 0.011 returned results which were either 986x(- up to 90) or 1076x(- up to 20).

Using 0.1 (and adjusting divisor to 10000) returned 9985(- up to 20).

(These tests were done on a Metro RP2040 running 9.2.0-beta.0)