How does time.sleep influence asyncio.sleep?

Async-SIG
1

I have the following code with two tasks: one task printing every second, the other just time.sleeping in 1s intervals:

import asyncio
import time


def log(msg):
    print(f"{time.monotonic():.2f} {msg}")


async def bg():
    while True:
        log("bg task")
        await asyncio.sleep(1)


async def sleep():
    while True:
        log("time.sleep")
        time.sleep(1)
        await asyncio.sleep(0)


async def main():
    bg_task = asyncio.create_task(bg())
    sleep_task = asyncio.create_task(sleep())
    await asyncio.Future()


asyncio.run(main())

I would have expected to see an output of both tasks about every second with maybe some hiccups in the ordering because of race conditions. Instead, what I see is this:

22663.50 bg task
22663.50 time.sleep
22664.50 time.sleep
22665.50 time.sleep
22666.50 bg task
22666.50 time.sleep
22667.50 time.sleep
22668.50 time.sleep
22669.50 bg task
22669.51 time.sleep
22670.51 time.sleep
22671.51 time.sleep
22672.51 bg task

Why is the background task only running every 3s? Is the time.sleep messing with the sleep timer in an asyncio loop? Thanks for any hints on this topic.

Cheers,
Tom

2

time.sleep() essentially pauses the entire OS-level thread, so the event loop cannot make progress while stuck in there. It’s not safe to use with asyncio, but I understand this is a toy example.

If you were expecting them to cleanly alternate, that’s kind of an implementation detail of how a particular event loop (or even a version of an event loop) handles scheduling internally. I wouldn’t rely on any particular ordering here.

2 Likes
3

Thanks @Tinche for your comment. I would have expected for asyncio.sleep to use wall clock time and after a wake-up to detect that one second has already passed.

I also don’t understand why forcibly pausing the event loop would make the other tasks wait for 3s instead of just 1. If I replace the time.sleep with a busy wait, the behavior is exactly the same so time.sleep cannot be the actual culprit here.

On the other hand, if I don’t return to the event loop using await asyncio.sleep(0) but with await asyncio.sleep(1e-20) everything works as expected. It seems as if asyncio.sleep behaves completely different (IMHO unexpected) when using a delay of 0.

4

It literally does: cpython/Lib/asyncio/tasks.py at 69cfad0b3e1e2805914cb647cce4c7c2bfed5910 · python/cpython · GitHub :wink:

In your sleep() coroutine, after time.sleep(1) you execute a suspend point with asyncio.sleep(0). This is an opportunity for the event loop to perform scheduling. From the perspective of the event loop, both sleep() and bg() are essentially equal candidates at this point. So it chooses to run sleep() again. If you went through the source code of the event loop carefully you’d probably find out why, but this is technically a race condition, and races gonna race.

2 Likes
5

I checked the code and saw the if branch, but was expecting that the await __sleep0() behaves practically like an await asyncio.sleep(1e-20), but it doesn’t.

I would understand if the background task is run every two seconds or that the ordering of the prints sometimes changes, but it’s always the same ordering and always after three seconds which IMHO cannot be reduced to just a race condition.

6

What OS did you run the code on? With IDLE on Windows, I get essentially the same result.

I am puzzled also, but to understand better, would look at Task.__step’s special handling of the __sleep0 coroutine and what loop.call_later(positive_delay, …) does.

7

I ran the code on Linux (Fedora 42) and Python 3.12.7 (same result with 3.13.7).

8

I didn’t mean ‘race condition’ as in non-deterministic behavior. I meant ‘race condition’ as in two things need to occur as the same time, and the system is free to choose either one (both are correct).

Usually event loops essentially have two data structures internally: a list of things to run on the next tick, and a heap of scheduled things to run at a certain point in time. When you block the event loop for a second with the time.sleep() and then yield, you kind of put it in an awkward position since continuing sleep() and continuing bg() are both valid choices.

I imagine (it’s been a while since I looked over this code in detail) continuing bg()is probably a two-step process (one tick runs a callback from asyncio.sleep() resolving an internal future, and the next tick wakes up the task waiting on that future), so that’s why you see sleep / sleep / bg.

1 Like
9

It’s even worse: sleep / sleep / sleep / bg, right? Anyway, thanks for your insights! That’s a great explanation for an unexpected behavior.

10

If you run await asyncio.sleep(0) exactly three times back to back (or await asyncio.sleep(1e-100) once), it behaves as expected.