Async Python: Debug Mode and Warnings
Enable asyncio Debug Mode
See the Python docs for all the ways to turn on async debug mode.
Warnings about blocking async code
In debug mode, you will get warnings about async code that blocks for too long as well as other warnings.
Example code:
import asyncio
import time
async def blocks():
print("START")
# Synchronous blocking code
time.sleep(0.35)
await asyncio.sleep(0.5)
# Synchronous blocking code
time.sleep(0.15)
await asyncio.sleep(0.1)
print("DONE")
asyncio.run(blocks(), debug=True)
Output:
START
Executing <Task pending name='Task-804' coro=<blocks() running at <ipython-input-7-1388d45e4cc5>:4> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f71d70e7910>()] created at /usr/lib/python3.9/asyncio/base_events.py:424> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:621> took 0.351 seconds
Executing <Task pending name='Task-804' coro=<blocks() running at <ipython-input-7-1388d45e4cc5>:6> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f71d8450430>()] created at /usr/lib/python3.9/asyncio/base_events.py:424> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:621> took 0.151 seconds
DONE
The time.sleep
function simulates running blocking synchronous code.
Notice we get warnings about how long the coroutine blocks every time the async function
spends too long blocking the async loop.
Solutions
- Optimizing the blocking code.
- Breaking up the blocking code into multiple async tasks.
- Running the code in a thread with
asyncio.to_thread
or with a custom executor andloop.run_in_executor
.
Change the warning threshold
If you find that you need a higher or lower threshold for warnings about
async code that blocks the main loop for too long, you can set it by changing the
slow_callback_duration
attribute of the async loop:
loop.slow_callback_duration = 0.15
If you don’t have access to the loop, you are likely using the default loop. In this case use:
asyncio.get_event_loop().slow_callback_duration = 0.15
This attribute has been available since Python 3.6, and maybe before that.
Default warning threshold value
The default as of Python 3.10 (in 2021) is 0.1
seconds.
Change the log handler
You can adjust the asyncio logger by getting the "asyncio"
logging.Logger
.
The default level of logging.DEBUG
may be too verbose, so you can set its
logging level to logging.WARNING
.
import logging
logger: logging.Logger = logging.getLogger("asyncio")
logger.setLevel(logging.WARNING)
json_logging_handler = ...
logger.addHandler(json_logging_handler)
Use aiodebug
If you don’t want to turn on debug mode in production, use aiodebug to log warnings when callbacks block the event loop:
aiodebug.log_slow_callbacks.enable(0.15)
This works by wrapping asyncio.events.Handler._run
with a timing and logging function.
To modify the logger’s output, you need to use the logger named after a specific file in the aiodebug project.
This may work:
import aiodebug.log_slow_callbacks
logger = logging.getLogger(aiodebug.log_slow_callbacks.__name__)