asyncio created and run tasks are delayed by "max 8 bit integer value ms" (66s) instead of running asap.

[reapzor]

CircuitPython version

Using the latest main of asyncio https://github.com/adafruit/Adafruit_CircuitPython_asyncio
Using the latest ticks https://github.com/adafruit/Adafruit_CircuitPython_Ticks
Using "A" latest circuitpython nightly: adafruit-circuitpython-unexpectedmaker_tinys3-en_US-20231018-eae426e.bin

Adafruit CircuitPython 9.0.0-alpha.1-74-geae426ed90 on 2023-10-18; TinyS3 with ESP32S3
Board ID:unexpectedmaker_tinys3
UID:4F21AFD4FF0B
boot.py output:

Code/REPL

import asyncio
import time

async def test_method():
    print("Time inside test_method:", time.monotonic())
    print("Running test_method")

async def sleepABit():
    print("Time inside sleepABit:", time.monotonic())
    for _ in range(10):
        print("Running sleepABit")
        await asyncio.sleep_ms(10000)
        asyncio.create_task(test_method())

print("Time before asyncio.create_task(test_method()):", time.monotonic())
asyncio.create_task(test_method())
print("Time before asyncio.run(sleepABit()):", time.monotonic())
asyncio.run(sleepABit())
print("Time after asyncio.run(sleepABit()):", time.monotonic())

Behavior

code.py output:
Time before asyncio.create_task(test_method()): 6878.4
Time before asyncio.run(sleepABit()): 6878.4

t.ph_key and ticks is 6878402 6812867
(poll 65534) 0

t.ph_key and ticks is 6878402 6878402
(poll 0) 0
Time inside test_method: 6943.94 - 66 seconds after calling run()
Running test_method

t.ph_key and ticks is 6878403 6878405
(poll 0) 0
Time inside sleepABit: 6943.94 - 66 seconds after calling run()
Running sleepABit

t.ph_key and ticks is 6888407 6878407
(poll 9999) 0

t.ph_key and ticks is 6888407 6888407
(poll 0) 0
Running sleepABit - 10 second sleep. this is correct.

t.ph_key and ticks is 6898409 6888410
(poll 9999) 0

t.ph_key and ticks is 6898409 6898410
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6908413 6898413
(poll 9999) 0

t.ph_key and ticks is 6908413 6908413
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6918415 6908416
(poll 9999) 0

t.ph_key and ticks is 6918415 6918416
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6928418 6918419
(poll 9999) 0

t.ph_key and ticks is 6928418 6928419
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6938421 6928422
(poll 9999) 0

t.ph_key and ticks is 6938421 6938421
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6948422 6938423
(poll 9999) 0

t.ph_key and ticks is 6948422 6948423
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6953945 6948426
(poll 5519) 0

t.ph_key and ticks is 6953945 6953946
(poll 0) 0
Time inside test_method: 7019.48 - But the next task took another 66 seconds before it ran. It should have run immediately
Running test_method

t.ph_key and ticks is 6958425 6953949
(poll 4475) 0

t.ph_key and ticks is 6958425 6958426
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6963949 6958429
(poll 5519) 0

t.ph_key and ticks is 6963949 6963949
(poll 0) 0
Time inside test_method: 7029.49 - And now it is running mostly as expected, but with a 66 second delay forced up front.
Running test_method

t.ph_key and ticks is 6968429 6963952
(poll 4477) 0

t.ph_key and ticks is 6968429 6968430
(poll 0) 0
Running sleepABit

t.ph_key and ticks is 6973951 6968433
(poll 5518) 0

t.ph_key and ticks is 6973951 6973952
(poll 0) 0
Time inside test_method: 7039.49
Running test_method

t.ph_key and ticks is 6978433 6973955
(poll 4478) 0

t.ph_key and ticks is 6978433 6978434
(poll 0) 0
Time after asyncio.run(sleepABit()): 7043.97

WORKING LOG WHEN USING MONOTONIC_NS FOR TICKS

code.py output:
using time monotonic_ns for ticks_ms
Time before asyncio.create_task(test_method()): 7944.83
Time before asyncio.run(sleepABit()): 7944.83
t.ph_key and ticks is 7944833 7944834
(poll 0) 0
Time inside test_method: 7944.83
Running test_method
t.ph_key and ticks is 7944833 7944837
(poll 0) 0
Time inside sleepABit: 7944.84
Running sleepABit
t.ph_key and ticks is 7954840 7944840
(poll 9999) 0
t.ph_key and ticks is 7954840 7954841
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 7954843 7954844
(poll 0) 0
Time inside test_method: 7954.85
Running test_method
t.ph_key and ticks is 7964844 7954847
(poll 9996) 0
t.ph_key and ticks is 7964844 7964845
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 7964847 7964848
(poll 0) 0
Time inside test_method: 7964.85
Running test_method
t.ph_key and ticks is 7974848 7964851
(poll 9996) 0
t.ph_key and ticks is 7974848 7974849
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 7974851 7974852
(poll 0) 0
Time inside test_method: 7974.85
Running test_method
t.ph_key and ticks is 7984852 7974855
(poll 9996) 0
t.ph_key and ticks is 7984852 7984852
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 7984855 7984856
(poll 0) 0
Time inside test_method: 7984.86
Running test_method
t.ph_key and ticks is 7994856 7984859
(poll 9996) 0
t.ph_key and ticks is 7994856 7994857
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 7994860 7994861
(poll 0) 0
Time inside test_method: 7994.86
Running test_method
t.ph_key and ticks is 8004860 7994864
(poll 9995) 0
t.ph_key and ticks is 8004860 8004860
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 8004863 8004864
(poll 0) 0
Time inside test_method: 8004.87
Running test_method
t.ph_key and ticks is 8014863 8004867
(poll 9995) 0
t.ph_key and ticks is 8014863 8014863
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 8014866 8014867
(poll 0) 0
Time inside test_method: 8014.87
Running test_method
t.ph_key and ticks is 8024866 8014870
(poll 9995) 0
t.ph_key and ticks is 8024866 8024866
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 8024869 8024870
(poll 0) 0
Time inside test_method: 8024.87
Running test_method
t.ph_key and ticks is 8034869 8024873
(poll 9995) 0
t.ph_key and ticks is 8034869 8034870
(poll 0) 0
Running sleepABit
t.ph_key and ticks is 8034873 8034874
(poll 0) 0
Time inside test_method: 8034.88
Running test_method
t.ph_key and ticks is 8044873 8034877
(poll 9995) 0
t.ph_key and ticks is 8044873 8044873
(poll 0) 0
Time after asyncio.run(sleepABit()): 8044.88

Description

AsyncIO doesn't seem to be working.
Creating a task, telling it to run, either case, the task won't run. At least it seems like it won't run.
The tasks actually do seem to run, but after 66 seconds of delay.
If I then await sleep. It will sleep fine. If I add another task. It will be another 66 seconds before it runs.

In asyncio we get this part of "run_until_complete()"

    while True:
        # Wait until the head of _task_queue is ready to run
        dt = 1
        while dt > 0:
            dt = -1
            t = _task_queue.peek()
            if t:
                # A task waiting on _task_queue; "ph_key" is time to schedule task at
                dt = max(0, ticks_diff(t.ph_key, ticks()))
            elif not _io_queue.map:
                # No tasks can be woken so finished running
                return
            print('(poll {})'.format(dt), len(_io_queue.map))
            _io_queue.wait_io_event(dt)

It's hanging up in
_io_queue.wait_io_event(dt)
Specifically this line
for s, ev in self.poller.ipoll(dt):

Note that dt seems to be absurdly off, printing out what seem to be "max 8 bit int" value when it should be, honestly, 0.

when looking at it I am noticing something odd with t.ph_key
this is controlled by the Task class - which from what I see, comes from native land, so at the layer I'm at I can't see whats happening yet.

try:
    from _asyncio import TaskQueue, Task

So something seems rather wrong with the native _asyncio logic. Not sure if this is coming from micropython but this was working in circuitpython for a while so not fully sure what happened.

Notice however, that once the initial task kicks off, it seems like sleep behaves appropriately. but any task that is created using "create_task" always seems to force a wait of 66 seconds before it will execute

Expect:
When I call asyncio.run(sleepABit()) asyncio should quickly kick into gear and execute both of the async methods I fed into it with little to no delay. They should execute "immediately, or as soon as asyncio allows tasks to start executing when run() is called"

Actual:
When I call asyncio.run(sleepABit()) both this task and the task created before are forced to wait 66 seconds before they run
When I add more tasks while asyncio is running, they too take 66 seconds to run.
asyncio sleep seems to behave normaly.

Workaround:
Use the pure python asyncio TaskQueue and Task for now. Something seems wrong with the native _asyncio Task/TaskQueue class.

Additional information

Curious Workaround
The logic also kicks into gear if you switch the adafruit ticks library to use monotonic_ns for ticks_ms instead of supervisor ticks_ms.

So not sure if this is actually a bug with supervisor ticks_ms() I am seeing.

[reapzor]

Oh
I think this is it

https://github.com/adafruit/circuitpython/pull/8481/files#diff-e2baf888039fbdf18dc4d8600714a0a332a02c995a694d98910671bc262ba7a5L73

// CIRCUITPY-style ticks
#define _TICKS_PERIOD (1lu << 29)
#define _TICKS_MAX (_TICKS_PERIOD - 1)
#define _TICKS_HALFPERIOD (_TICKS_PERIOD >> 1)
#if !CIRCUITPY || (defined(__unix__) || defined(__APPLE__))
STATIC mp_obj_t ticks(void) {
    return MP_OBJ_NEW_SMALL_INT(mp_hal_ticks_ms() & _TICKS_MAX);
}
#else
// We don't share the implementation above because our supervisor_ticks_ms
// starts the epoch about 65 seconds before the first overflow (see
// shared-bindings/supervisor/__init__.c). We assume/require that
// supervisor.ticks_ms is picked as the ticks implementation under
// CircuitPython for the Python-coded bits of asyncio.
#define ticks() supervisor_ticks_ms()
#endif

I think this patch was accidentally removed or perhaps thought wasn't needed? Seems very relative to the issue I am seeing.

[dhalbert]

Thanks for the diagnosis! If you have a build environment for CircuitPython, could you try adding back the code? A PR to fix would be welcome. Otherwise we'll take a look early this week.