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:

1. Sleep Task
2. I/O-Bound Task
3. 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:

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:

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:

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:

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:

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:

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:

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:

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.

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.

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

Tying this together, the complete example is listed below.

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.

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:

This would report:

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.

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

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.

Tying this together, the complete example is listed below.

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.

Further Reading

This section provides additional resources that you may find helpful.

Python Asyncio Books

• Python Asyncio Mastery, Jason Brownlee (my book!)
• Python Asyncio Jump-Start, Jason Brownlee.
• Python Asyncio Interview Questions, Jason Brownlee.
• Asyncio Module API Cheat Sheet

I also recommend the following books:

• Python Concurrency with asyncio, Matthew Fowler, 2022.
• Using Asyncio in Python, Caleb Hattingh, 2020.
• asyncio Recipes, Mohamed Mustapha Tahrioui, 2019.

Guides

• Python Asyncio: The Complete Guide
• Python Asynchronous Programming

APIs

• asyncio — Asynchronous I/O
• Asyncio Coroutines and Tasks
• Asyncio Streams
• Asyncio Subprocesses
• Asyncio Queues
• Asyncio Synchronization Primitives

References

• Asynchronous I/O, Wikipedia.
• Coroutine, Wikipedia.

Takeaways

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

Did I make a mistake? See a typo?
I’m a simple humble human. Correct me, please!

Do you have any additional tips?
I’d love to hear about them!

Do you have any questions?
Ask your questions in the comments below and I will do my best to answer.

Photo by matthew cann on Unsplash