Why CPU bound task doesn't block asyncio event loop?

I want to go deep in asynchronous task execution in python and I made experiment when CPU Bound task runs with IO bound task simultaneously.

I suppose that CPU Bound task blocks the event loop and IO Bound task will start after CPU Bound task finished. But in my experiment I see that IO Bound task start and finishes simultaneously with CPU Bound. I want to find answer, why it happens.

To make IO bound load I use asyncio.sleep, to make CPU bound load I use for loop with multiplying and division.

Experiment code:

import asyncio
from datetime import datetime

async def io_bound(i):
    print(f'start io_bound {i} {datetime.now().strftime("%H:%M:%S")}')
    await asyncio.sleep(1)
    print(f'finish io_bound {i} {datetime.now().strftime("%H:%M:%S")}')

async def cpu_bound():
    print(f'start cpu_bound {datetime.now().strftime("%H:%M:%S")}')
    for i in range(5 * 10**7):
        i *= i+1
        i /= i+1
    print(f'finish cpu_bound {datetime.now().strftime("%H:%M:%S")}')

async def main():
    await io_bound(1)
    asyncio.create_task(cpu_bound())
    await io_bound(2)

loop = asyncio.new_event_loop()
asyncio.set_event_loop(loop)
loop.run_until_complete(main())

output:

start io_bound 1 17:28:20
finish io_bound 1 17:28:21
start io_bound 2 17:28:21
start cpu_bound 17:28:21
finish cpu_bound 17:28:26
finish io_bound 2 17:28:26

I expected that output should be:

start io_bound 1 17:28:20
finish io_bound 1 17:28:21
start io_bound 2 17:28:21
start cpu_bound 17:28:21
finish cpu_bound 17:28:26
finish io_bound 2 17:28:27

That is, io_bound task should finish one second after cpu_bound is finished.

So the question is: Why io_bound finishes immediately after cpu_bound is finished? Doesn't CPU bound task block execution of other tasks?

Thanks for any responses.

UPD: thanks all for the explanations.

I made more real io_bound task using simple fastapi server, which I ran in background and call endpoint using aiohttp. Also I added await asyncio.sleep(0.0001) to make cpu_bound() task starts before io_bound(2) and now I see desired timings which explains blocking event loop. Actually I think with await asyncio.sleep(0.0001) as task delimiter, event loop also will be blocked with "synthetic" examples, like time.sleep() for cpu-bound and await asyncio.sleep() for io-bound, but I like more real examples.

Server snippet:

# server.py fastapi server, run it with 'fastapi dev server.py'

import asyncio
from fastapi import FastAPI

app = FastAPI()

@app.get("/io-bound")
async def extract():
    await asyncio.sleep(1.5)
    return 200

Experiment snippet:

import asyncio
import aiohttp
from datetime import datetime


async def io_bound(i):
    print(f'start io_bound {i} {datetime.now().strftime("%H:%M:%S.%f")}')
    url = 'http://localhost:8000/io-bound'
    async with aiohttp.ClientSession() as session:
        async with session.get(url) as resp:
            await resp.text()
    print(f'finish io_bound {i} {datetime.now().strftime("%H:%M:%S.%f")}')


async def cpu_bound():
    print(f'start cpu_bound {datetime.now().strftime("%H:%M:%S.%f")}')
    for i in range(5 * 10**7):
        i *= i+1
        i /= i+1
    print(f'finish cpu_bound {datetime.now().strftime("%H:%M:%S.%f")}')


async def main():
    await io_bound(1)
    asyncio.create_task(cpu_bound())
    await asyncio.sleep(0.0001)
    await io_bound(2)


loop = asyncio.new_event_loop()
asyncio.set_event_loop(loop)

loop.run_until_complete(main())

Output:

start io_bound 1 19:50:49.948834
finish io_bound 1 19:50:51.454851
start cpu_bound 19:50:51.455090
finish cpu_bound 19:50:56.684384
start io_bound 2 19:50:56.684557
finish io_bound 2 19:50:58.188327

Solution

The asyncio.sleep(1) tells the asyncio scheduler to stop running the current task now and to schedule to run it again one second from now. This inserts a TimerHandle object (a low-level timed callback) to the queue of waiting TimerHandles.

The queue is sorted by the time of desired action. In order to be able to sort it, the time must be absolute. The "one second from now" is also stored as an absolute time.

The event loop is then blocked by a CPU bound task for few seconds. When the loop gains control again, the scheduled TimerHandle is already too late, so it is run immediately.

You could try asyncio.sleep(10) to verify that it means continue 10 seconds from now.