asyncio: sleep_ms terminates early
Port, board and/or hardware
STM32, RP2
MicroPython version
MicroPython v1.24.0-preview.31.g3c8089d1b on 2024-06-06; Raspberry Pi Pico with RP2040
Reproduction
Pasted the following at the REPL:
import asyncio
import time
async def do_nothing():
while True:
await asyncio.sleep_ms(0)
async def test():
asyncio.create_task(do_nothing())
for i in range(1, 55):
start = time.ticks_us()
await asyncio.sleep_ms(i)
t = time.ticks_diff(time.ticks_us(), start)
tt = 1000 * i # Target time in us
print(f"{i} {tt} {t} δ = {t - tt} μs")
asyncio.run(test())
Expected behaviour
Expected the value of δ always to be a positive integer.
On STM32:
1 1000 990 δ = -10 μs
2 2000 1687 δ = -313 μs
3 3000 2845 δ = -155 μs
4 4000 3676 δ = -324 μs
5 5000 4838 δ = -162 μs
6 6000 5668 δ = -332 μs
7 7000 6834 δ = -166 μs
8 8000 7662 δ = -338 μs
9 9000 8821 δ = -179 μs
10 10000 9652 δ = -348 μs
11 11000 10817 δ = -183 μs
12 12000 11645 δ = -355 μs
13 13000 12805 δ = -195 μs
14 14000 13635 δ = -365 μs
15 15000 14803 δ = -197 μs
16 16000 15796 δ = -204 μs
17 17000 16622 δ = -378 μs
18 18000 17784 δ = -216 μs
19 19000 18788 δ = -212 μs
20 20000 19778 δ = -222 μs
21 21000 20606 δ = -394 μs
22 22000 21767 δ = -233 μs
23 23000 22773 δ = -227 μs
24 24000 23764 δ = -236 μs
25 25000 24756 δ = -244 μs
26 26000 25751 δ = -249 μs
27 27000 26757 δ = -243 μs
28 28000 27748 δ = -252 μs
29 29000 28739 δ = -261 μs
30 30000 29734 δ = -266 μs
31 31000 30741 δ = -259 μs
32 32000 31731 δ = -269 μs
33 33000 32722 δ = -278 μs
34 34000 33718 δ = -282 μs
35 35000 34728 δ = -272 μs
36 36000 35716 δ = -284 μs
37 37000 36704 δ = -296 μs
38 38000 37868 δ = -132 μs
39 39000 38713 δ = -287 μs
40 40000 39700 δ = -300 μs
41 41000 40689 δ = -311 μs
42 42000 41851 δ = -149 μs
43 43000 42697 δ = -303 μs
44 44000 43684 δ = -316 μs
45 45000 44838 δ = -162 μs
46 46000 45668 δ = -332 μs
47 47000 46683 δ = -317 μs
48 48000 47835 δ = -165 μs
49 49000 48656 δ = -344 μs
50 50000 49818 δ = -182 μs
51 51000 50667 δ = -333 μs
52 52000 51819 δ = -181 μs
53 53000 52639 δ = -361 μs
54 54000 53801 δ = -199 μs
Observed behaviour
On STM32 δ is negative by up to 400μs. On RP2 it is usually positive but occasionally negative by up to 450μs.
Additional Information
This arose in https://github.com/orgs/micropython/discussions/15594#discussioncomment-10253183.
I doubt this is a practical problem but it does seem a surprising result.
Code of Conduct
Yes, I agree
RP2: time.sleep and time.sleep_ms waking early (but not time.sleep_us)
Port, board and/or hardware
RP2 (Pico 2W)
MicroPython version
MicroPython v1.25.0 on 2025-04-15; Raspberry Pi Pico 2 W with RP2350
Reproduction
sleep:
>>> for _ in range(0, 10): a = time.ticks_us() ; time.sleep(0.002) ; b = time.ticks_us() ; print(b - a) ;
...
1900
1767
1883
1868
1882
1894
1918
1885
1902
1901
sleep_ms:
>>> for _ in range(0, 10): a = time.ticks_us() ; time.sleep_ms(2) ; b = time.ticks_us() ; print(b - a) ;
...
1957
1782
1917
1881
1895
1883
1903
1902
1905
1899
sleep_us:
>>> for _ in range(0, 10): a = time.ticks_us() ; time.sleep_us(2000) ; b = time.ticks_us() ; print(b - a) ;
...
2035
2033
2022
2022
2020
2021
2022
2021
2022
2027
Expected behaviour
Expecting sleep times to be at least the requested duration (except, of course, in the case of an exception being thrown).
Observed behaviour
thread.sleep and thread.sleep_ms wake early for this particular (2ms) duration, but thread.sleep_us does not.
Additional Information
I discovered this because an I2C sensor driver was intermittently failing due to not sleeping long enough when resetting a device (its code follows the sensor specification of waiting 2ms, or at least it tries to).
https://github.com/micropython/micropython/issues/15626 may or may not be related, I don't know nearly enough about micropython at this point to say.
Code of Conduct
Yes, I agree