time.sleep() narcoleptic on nRF52840 (Feather Sense)

[ericwertz]

Short calls to time.sleep(t) end up sleeping for 1.0+t seconds. Found this by sleeping for short periods between bit-banging through the phases of a four-phase stepper. It would simply stop multiple times per minute for exactly one second, then continue.

This happens on multiple Sense boards but I have not been able to reproduce it on the M4 running it for (only) 10 minutes.

import time

while True:
    t0 = time.monotonic()
    time.sleep(0.002)
    t = time.monotonic() - t0
    if t > 0.1: print("[redacted]! ", t0, t)

In addition to the as-shown example, this test continues to fail with args up to (at least) 0.025.

[dhalbert]

Which version of CircuitPython are you testing?

Please do not use profanity.

[dhalbert]

Tested with 9.2.4, with the test program above. Sample output:

10.573 2.05
45.391 2.048
108.878 2.048

Note now the 2 second delay rather than 1 second.

[Neradoc]

Issue #7613 was tied to BLE being in use, but I can actually reproduce something similar without using BLE.

So testing the code above on a Seeed Xiao NRF52840 and Feather NRF52840 Express I discovered that the sleep times are related to the operating system used. I made the code a little more complex so I can see the time values when it's going well without overwhelming the logs, and see it freeze:

import time
bad = False
while True:
    t0 = time.monotonic()
    time.sleep(0.002)
    t1 = time.monotonic()
    dt = (t1 - t0)
    if dt > 0.1:
        print()
        print(f"{t0:10.3f} - {dt:10.6f}", "<--")
        bad = True
    else:
        print(f"{t0:10.3f} - {dt:10.6f}")
        if not bad:
            print("\033[1A", end="") # writes over the last line
        bad = False

Resulting in long sleeps on my Mac.

 1206.446 -   0.001953
  1206.448 -  65.052246 <--
  1271.500 -   0.001953
  1296.836 -   0.001953
  1296.838 - 239.162109 <--
  1536.000 -   0.001953
  1568.021 -   0.001953
  1568.023 -  35.569824 <--
  1603.595 -   0.001953

However when I connect the board to my windows machine I get smaller random sleeps ranging between 0.1 and 1.0 seconds.

   827.756 -   0.001251
   827.757 -   0.925018 <--
   828.683 -   0.001282
   829.110 -   0.001282
   829.112 -   0.578308 <--
   829.692 -   0.001770
   830.213 -   0.001373
   830.216 -   0.476563 <--
   830.693 -   0.001251
   834.569 -   0.001312
   834.571 -   0.155457 <--
   834.727 -   0.001282
   836.357 -   0.001312
   836.359 -   0.392487 <--
   836.752 -   0.001556
   837.609 -   0.001251
   837.611 -   0.152069 <--
   837.764 -   0.001709
   837.820 -   0.001343
   837.822 -   0.953400 <--
   838.776 -   0.001221
   840.017 -   0.001373
   840.019 -   0.769623 <--
   840.790 -   0.001434
   841.013 -   0.001190
   841.015 -   0.608734 <--
   841.625 -   0.001221
   841.801 -   0.001282

When connected to my Raspberry Pi I get seemingly the same experience as Dan with 2.0 seconds rogue sleeps:

    36.655 -   0.001404
    36.657 -   2.059570 <--
    38.717 -   0.001801
    38.721 -   0.001434
    38.723 -   2.073242 <--
    40.797 -   0.001862
    40.799 -   0.001526
    40.801 -   2.075104 <--
    42.877 -   0.001892
    42.892 -   0.001434
    42.894 -   2.062408 <--
    44.957 -   0.001953
    44.995 -   0.001465
    44.997 -   2.039948 <--
    47.037 -   0.001984
    47.051 -   0.001404
    47.053 -   2.063416 <--
    49.117 -   0.001953

I noted, on all platforms, that a sleep can be interrupted by typing a key while in a serial window (so, causing a USB interrupt or something ?)

So, is it possible that those operating systems "ping" USB devices differently, causing the board to wake up from its abnormal sleep in different patterns ? Or something entirely different...

[slaxor505]

I hit this one when building this project https://github.com/rafgaj/Mouse-Ring-v2
The bug is very nasty as I spent around 2 month to figure out what's going on because it appears randomly.

[ericwertz]

tWhen I reported this over four years ago, my usage was exactly as described, no BLE or anything else involved -- all six lines of code are there, excepting the text of my print statement which was redacted due to boo-hoo.

The reality is that Pythons aren't a particularly good choice for semi-realtime use due to internals of its design that can make it a pretty bad fit for tight-timing or even medium-latency applications. Just as it took about 30 years for Un*x OSes to be usable for "kind of" realtime applications, current Pythons fall down for similar reasons. You can use it for a quite a bit of stuff (including/especially prototyping), but its wheels break off when you start to lean on it for things that it wasn't designed for.

[dhalbert]

I think this still might be a bug, so I'm reopening it. @slaxor505: which version of CircuitPython were you using? How often does it appear? If you could re-test with 10.0.0-alpha.6, which has some time stuff rewritten, that would be great, but if it takes a potentially long time for the extra-long sleep to appear, it might be hard to test.

[ericwertz]

When this bug was submitted it took seconds to reproduce. But a LOT has likely changed since then, so all old bets are probably off as to how far this tick has burrowed down.

I think this still might be a bug, so I'm reopening it. @slaxor505: which version of CircuitPython were you using? How often does it appear? If you could re-test with 10.0.0-alpha.6, which has some time stuff rewritten, that would be great, but if it takes a potentially long time for the extra-long sleep to appear, it might be hard to test.