RP2 asyncio stream IO hangs: regression
Port, board and/or hardware
RP2040 or RP2350
MicroPython version
Fails on release builds >= 22.0
Bug seems RP2-specific: the script runs on STM32 (Pyboard 1.1) and ESP32-S3 with current firmware (1.27).
Reproduction
Either paste the script at the REPL or run from a file foo.py (mpremote mount . "exec import foo")
import asyncio # as asyncio
import time
import io
MP_STREAM_POLL_RD = const(1)
MP_STREAM_POLL = const(3)
MP_STREAM_ERROR = const(-1)
class MillisecTimer(io.IOBase):
def __init__(self):
self.end = 0
self.sreader = asyncio.StreamReader(self)
def __iter__(self):
await self.sreader.read(1)
def __call__(self, ms):
self.end = time.ticks_add(time.ticks_ms(), ms)
return self
def read(self, _):
return b"a"
def ioctl(self, req, arg):
ret = MP_STREAM_ERROR
#time.sleep_us(2_000)
if req == MP_STREAM_POLL: # hangs HERE
ret = 0
if arg & MP_STREAM_POLL_RD:
if time.ticks_diff(time.ticks_ms(), self.end) >= 0:
ret |= MP_STREAM_POLL_RD
return ret
async def timer_test(n):
timer = MillisecTimer()
for x in range(n):
await timer(100) # Pause 100ms
print(x)
asyncio.run(timer_test(20))
Expected behaviour
Expected to print integers from 0 to 19.
Observed behaviour
Hangs on the line commented with "hangs HERE".
Behaviour can be "fixed" by uncommenting the 2ms delay.
Additional Information
No, I've provided everything above.
Code of Conduct
Yes, I agree
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