Asyncio Log Long-Running Blocking Calls With aiodebug

January 25, 2024 Python Asyncio

You can identify and log asyncio tasks that block the event loop for too long.

Calling Python functions in asyncio programs rather than awaiting coroutines and tasks will block the event loop. Function calls that take a long time, such as those that perform file I/O or a CPU-bound task may cause the event loop to freeze and fail to progress for many seconds to minutes.

We can use the aiodebug third-party library to identify and log these long-running blocking tasks in our asyncio program.

In this tutorial, you will discover how to report and log asyncio tasks that make function calls that block the event loop for too long.

Let's get started.

Need to Know About Long-Running Blocking Function Calls

Long-running tasks in asyncio programs are a problem.

We can call functions in an asyncio function that are blocking.

This means that the entire asyncio event loop is blocked until the call is complete and no other coroutines are able to run.

This is a problem as the event loop will not progress. It is as though the program has frozen for the duration of the blocking call.

Technically, all function calls made in an asyncio program are blocking. Only some of them are a problem. Specifically, blocking calls that take "too long".

How can we identify and report all blocking calls in an asyncio program that takes too long?

How to Identify Long-Running Tasks with aiodebug

We can identify and report long-running blocking tasks in asyncio using the aiodebug package.

This is a third-party module that provides utilities for debugging asyncio programs.

tiny library for monitoring and testing asyncio programs
-- aiodebug Project, GitLab.

We can install the aiodebug Python package and configure it in our asyncio application to automatically report and even log those asyncio tasks that take too long.

We can also configure how long is too long for a blocking function call.

This is a tiny library for monitoring and testing asyncio programs. Its monitoring features are meant to be always on in production.
-- aiodebug Project, GitLab.

Note, the asyncio event loop provides this capability already, but only when configured to run in debug mode.

You can learn more about this in the tutorial:

How to Debug Asyncio

Gen really, we don't want to run our asyncio programs in debug mode in production, because the execution of our program may be significantly slower.

The aiodebug module provides just this capability without all of the event loop debug mode, allowing us to report long-running tasks in a production system.

asyncio already does this in debug mode, but you probably don't want to enable full-on debug mode in production.
-- aiodebug Project, GitLab.

What is a "long-running" Task?

A long-running task is a function call made in an asyncio coroutine that blocks the event loop for a long time, e.g. more than 50 milliseconds.

There are perhaps 3 main types of blocking calls in an asyncio program that we can make that might take a long time.

They are:

Sleep Task
I/O-Bound Task
CPU-Bound Task

Let's take a closer look at each in turn,

Blocking Sleep Task

A blocking sleep task is a call to time.sleep() in asyncio.

For example:

...
# block the event loop for a long time
time.sleep(5)

This will block the event loop.

We should not call time.sleep() in an asyncio program. If we need to sleep, we should await asyncio.sleep().

For example:

...
# suspend for a moment
await asyncio.sleep(5)

You can learn more about asyncio.sleep() in the tutorial:

Asyncio sleep() in Python

I/O-Bound Task

An I/O bound task is a function call that performs some I/O, such as read/write a file, socket, or subprocess.

Generally, asyncio does not support non-blocking file IO at the time of writing, so all file IO performed in asyncio will block the event loop.

For example:

...
# open file
with open(filepath) as file:
	# read file into memory
	data = file.read()

This will block the event loop.

Instead, we should perform file IO in a separate thread via asyncio.to_thread().

You can learn more about asyncio.to_thread() in the tutorial:

How to Use Asyncio to_thread()

If an asyncio program is performing blocking read/write on a socket or subprocess, these calls can be updated to use the non-blocking asyncio versions of the calls or the calls should be performed in another thread.

CPU-Bound Task

A CPU-bound task is a task that runs as fast as the CPU will permit.

This is a function call that performs compute or number crunching.

For example:

...
# block the event loop for a long time
data = [i*i for i in range(100000000)]

This will block the event loop until the work is complete.

Ideally, tasks of this type should be performed in another thread via asyncio.to_thread() or in another process via loop.run_in_executor().

You can learn more about running CPU-bound tasks outside of the event loop in the tutorial:

How to Run Blocking Tasks in Asyncio

Now that we know what a long-running task is, let's look at how we can use aiodebug to identify them.

How to Install aiodebug

The aiodebug library can be installed using your favorite package manager.

For example, we can install it using pip:

pip install aiodebug

That's it.

How to Report Long-Running Tasks with aiodebug

We can use aiodebug in our program to identify long-running tasks that block the asyncio event loop for "too long".

This can be achieved by calling the aiodebug.log_slow_callbacks.enable() function and specifying the time in seconds that a task takes that is too long.

For example:

import aiodebug.log_slow_callbacks

...
# set time in sec for long running tasks
aiodebug.log_slow_callbacks.enable(0.1)

When a task is completed, if it has blocked the event loop for longer than the specified time, then its details will be reported in standard output.

We can configure a handler function so that we can log these tasks.

This can be achieved by defining a function that takes the task and duration it ran as an argument and then logging it using the Python logging infrastructure.

For example:

# handler for long running tasks
def log_slow_handler(task, duration):
    # log the task
    logging.debug(f'Task blocked async loop for too long. Task {task} Duration {duration} ')

We can then configure the aiodebug package to call our function each time a task is done and has blocked the event loop for too long.

This can be achieved by calling the aiodebug.log_slow_callbacks.enable() function and specifying the "on_slow_callback" argument to equal the name of our function.

For example:

...
# enable logging of long running tasks
aiodebug.log_slow_callbacks.enable(1, on_slow_callback=log_slow_handler)

Limitation of aiodebug

The aiodebug module has some limitations.

Firstly, only the task is reported. A task may make many blocking calls and one or more of the calls may be "too long".

Nevertheless, reporting will only show a task that took too long.

Secondly, the aiodebug module will only report on tasks that take too long because they block the event loop. It does not report on tasks whose overall execution time took too long.

Many tasks perform correct async calls but take much longer than we would like. These will be missed by aiodebug.

Finally, the aiodebug will only report on tasks that block the event loop for more than the specified number of seconds. This means that if a coroutine is awaited that has a blocking call, it will be the parent task that awaits that coroutine that will be reported, not the coroutine.

To have coroutines names that make blocking calls reported directly, they must be run as independent tasks, e.g. tasks created via asyncio.create_task() or similar.

Now that we know how to use aiodebug and some of its limitations, let's look at some worked examples.

Example of Reporting Long-Running Tasks with aiodebug

We can explore an example of reporting a long-running blocking task with aiodebug.

In this example, we will define a task that blocks the event loop for a long time. We will then run this task from a coroutine. The aiodebug log_slow_callbacks capability will be enabled and report all tasks that block the event loop for longer than one second.

Firstly, we will define a coroutine that blocks the event loop with a call to time.sleep() for 5 seconds.

# long running task
async def work():
    # block the event loop for a long time
    time.sleep(5)

Next, we can define the main() coroutine that reports a message, awaits the work() coroutine that has the blocking function call, and then report a done message.

# main program
async def main():
    # report a message
    print('Main is running')
    # create the task
    task = asyncio.create_task(work())
    # await our task
    await task
    # report a message
    print('Main is done.')

Finally, we can enable long-task reporting with aiodebug and then start the event loop.

...
# enable logging of long running tasks
aiodebug.log_slow_callbacks.enable(1)
# start the event loop
asyncio.run(main())

Tying this together, the complete example is listed below.

# SuperFastPython.com
# example of logging long running tasks with aiodebug
import time
import asyncio
import aiodebug.log_slow_callbacks

# long running task
async def work():
    # block the event loop for a long time
    time.sleep(5)

# main program
async def main():
    # report a message
    print('Main is running')
    # create the task
    task = asyncio.create_task(work())
    # await our task
    await task
    # report a message
    print('Main is done.')

# enable logging of long running tasks
aiodebug.log_slow_callbacks.enable(1)
# start the event loop
asyncio.run(main())

Running the example first configures the aiodebug module to report tasks that block the event loop for more than one second.

It then starts the asyncio event loop and runs the main() coroutine.

The main() coroutine runs and reports a message. It then awaits the work() coroutine.

The work() coroutine runs and calls time.sleep() for 5 seconds.

This blocks the entire event loop for 5 seconds. In fact, it blocks the entire thread.

The call to time.sleep() returns and the work() coroutine resumes and terminates.

Once the task is done, the aiodebug module reports the task that took too long. It reports that the work() coroutine took more than 5 seconds to complete.

The main() coroutine resumes and reports a final message before terminating.

This highlights that we can use aiodebug to report tasks that block the event loop for too long.

Main is running
Executing result=None> took 5.001 seconds
Main is done.

Note, if we updated the example so that main() awaited the work() coroutine directly, then aiodebug would report on the main() task, and not the work() task. This would be misleading.

For example:

...
# await our task
await work()

This would report:

...
Executing <Task finished name='Task-1' coro=<main() done, defined at ...:13> result=None> took 5.004 seconds

This highlights a limitation of aiodebug, that it is focused on reporting on new tasks, not coroutines that are awaited.

Next, let's look at how we might update the example to log the long-running task.

Example of Logging Long-Running Tasks with aiodebug

We can explore an example that logs tasks that block the event loop for too long.

In this case, we will update the above example so that we define a custom handler function to be called when a task is done that blocked the event loop for too long. We will then configure the aiodebug module to call our custom handler.

Firstly, we can define our handler function to call when a task is done and blocked for too long.

The function must take the task object and the duration it was blocked in seconds as arguments.

We will log a debug message and include the details of the task and its duration.

# handler for long running tasks
def log_slow_handler(task, duration):
    # log the task
    logging.debug(f'Task blocked async loop for too long. Task {task} Duration {duration} ')

Before starting the event loop, we will configure the Python logging infrastructure to report all log messages with a DEBUG level and above.

...
# get the root logger
log = logging.getLogger()
# log all messages, debug and up
log.setLevel(logging.DEBUG)

We will then enable long-running task warnings via the aiodebug module and configure it to call our function handler each time a task is done that is blocked for more than one second.

...
# enable logging of long running tasks
aiodebug.log_slow_callbacks.enable(1, on_slow_callback=log_slow_handler)

Tying this together, the complete example is listed below.

# SuperFastPython.com
# example of logging long running tasks with aiodebug
import logging
import time
import asyncio
import aiodebug.log_slow_callbacks

# handler for long running tasks
def log_slow_handler(task, duration):
    # log the task
    logging.debug(f'Task blocked async loop for too long. Task {task} Duration {duration} ')

# long running task
async def work():
    # block the event loop for a long time
    time.sleep(5)

# main program
async def main():
    # report a message
    print('Main is running')
    # create the task
    task = asyncio.create_task(work())
    # await our task
    await task
    # report a message
    print('Main is done.')

# get the root logger
log = logging.getLogger()
# log all messages, debug and up
log.setLevel(logging.DEBUG)
# enable logging of long running tasks
aiodebug.log_slow_callbacks.enable(1, on_slow_callback=log_slow_handler)
# start the event loop
asyncio.run(main())

Running the example first configures the Python logging infrastructure to report all messages.

Next, the aiodebug module is configured to report all tasks that block the event loop for more than one second and to call our custom handler function as soon as the task is done.

It then starts the asyncio event loop and runs the main() coroutine.

The main() coroutine runs and reports a message. It then awaits the work() coroutine.

The work() coroutine runs and calls time.sleep() for 5 seconds.

This blocks the entire event loop for 5 seconds. In fact, it blocks the entire thread.

The call to time.sleep() returns and the work() coroutine resumes and terminates.

Once the task is done, the aiodebug module calls our custom handler function log_slow_handler() because the function took too long.

Our log_slow_handler() function runs and logs a debug message with the details of the work() task and that it blocked the event loop for longer than 5 seconds.

The main() coroutine resumes and reports a final message before terminating.

This highlights that we can use a custom handler to log messages as soon as tasks are done that block the event loop for too long.

Main is running
DEBUG:root:Task blocked async loop for too long. Task <Task finished name='Task-2' coro=<work() done, defined at ...:14> result=None> Duration 5.005230398033746
Main is done.

Takeaways

You now know how to report and log asyncio tasks that make function calls that block the event loop for too long.

If you enjoyed this tutorial, you will love my book: Python Asyncio Jump-Start. It covers everything you need to master the topic with hands-on examples and clear explanations.