Python asyncio sleep - taking excessive time

I have an asyncio app that I'm running that is quite time sensitive - so I'm trying to work through and tidy up any blocking code I can find.

I am using asyncio.run() with debug=True.

As you can see the I/O selector is blocked for 0.852 seconds waking up from sleep, as per the Python docs:

The execution time of the I/O selector is logged if it takes too long to perform an I/O operation.

20/04/23 12:04:20 WARNING  asyncio: Executing <Task pending name='Task-99' coro=<CodeRunner.run_forever() running at /code/testcode.py:929> wait_for=<Future pending cb=[Task.task_wakeup()]        base_events.py:1917
                           created at /Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py:427> cb=[_run_until_complete_cb() at
                           /Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py:180] created at
                           /Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/runners.py:100> took 0.852 seconds

The code in question:

        while True:
            if counter % CONTACT_SCHEDULE == 0:
                await self.run_once()
                counter = 0
                log.info(f"Sleeping {CONTACT_SCHEDULE} seconds...")

            progress.refresh()

            counter += 1
            await asyncio.sleep(1)  <--- this is line 929

My question is, why is asyncio.sleep(1) causing my code to hang? Is it because something else is running at the same time and blocking?

That's not a slow I/O selector message, and it's not saying that asyncio.sleep is the problem. That's a slow callback message, which you'll see described in the next bullet point in the asyncio debug mode docs after the part you quoted:

> * Callbacks taking longer than 100ms are logged. The loop.slow_callback_duration attribute can be used to set the minimum execution duration in seconds that is considered “slow”.

Judging by the details of the message, it looks like an internal callback used for Task.__step, which runs the coroutine a task is wrapping until the coroutine suspends.

asyncio.sleep isn't the problem. It's just where your coroutine happened to suspend. The warning message is trying to tell you that your coroutine ran continuously for 0.852 seconds between when it woke up and when it suspended for asyncio.sleep.

We can't tell why your coroutine took that long. It sounds like something very slow and synchronous happened in self.run_once or progress.refresh, but we don't have enough info to say anything about what that was.

I think your call to asyncio.sleep(1) uses the default event loop here which creates the problem you're facing.

Instead, pass your event loop as a parameter as a parameter to asyncio

await asyncio.sleep(1, loop=referenceToYourEventLoop)