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

Start by running the supplied REPL reproduction on the STM32 or RP2040 targets, focusing on asyncio.sleep_ms(), asyncio.create_task(), and time.ticks_us(). Compare the measured delays with the requested milliseconds and trace the asyncio sleep scheduling path. Done means the reproduction no longer shows sleep_ms() returning early, or the timing behavior is documented as intentional.