how to use slow_callback_duration to find blocking coroutines in asyncio

Question

I'm debugging some code where one coroutine is, I think, blocking another coroutine causing it to time out. I don't know where that is. I believe this toy code models my situation, or at least, a situation I want to understand:

import asyncio
import logging
import sys
import time
import warnings

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s - %(levelname)7s: %(message)s",
    stream=sys.stderr,
)
logger = logging.getLogger("")
LOG = logger


async def timeout_checker():
    logger.info("starting timeout clock")
    t0 = time.time()
    await asyncio.sleep(0.1)
    if time.time() - t0 > 3:
        raise asyncio.TimeoutError("timeout!")


async def selfish_sleeper():
    logger.info("selfish sleeping")
    time.sleep(4)
    logger.info(f"done sleeping")


async def two_level_sleeper():
    await selfish_sleeper()


async def timeshare():
    task = asyncio.create_task(timeout_checker())

    logger.info(f"created task, starting unselfish sleep")
    await asyncio.sleep(0.05)

    # await selfish_sleeper()
    await two_level_sleeper()

    result = await task
    logger.info(f"result {result}")


async def main():
    event_loop = asyncio.get_event_loop()

    # Enable debugging
    event_loop.set_debug(True)

    # Make the threshold for "slow" tasks very very small for
    # illustration. The default is 0.1, or 100 milliseconds.
    event_loop.slow_callback_duration = 0.001

    # Report all mistakes managing asynchronous resources.
    warnings.simplefilter("always", ResourceWarning)

    await timeshare()


if __name__ == "__main__":
    logger.info("start")
    asyncio.run(main(), debug=True)
    logger.info("done")

In this toy, I was hoping to find something that could just tell me that selfish_sleeper is taking more time than expected. When I run this, I get:

2021-11-29 14:16:51,439 -    INFO: start
2021-11-29 14:16:51,440 -   DEBUG: Using selector: EpollSelector
2021-11-29 14:16:51,464 -    INFO: created task, starting unselfish sleep
2021-11-29 14:16:51,468 - WARNING: Executing  wait_for= cb=[_run_until_complete_cb() at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/base_events.py:184] created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 0.012 seconds
2021-11-29 14:16:51,468 -    INFO: starting timeout clock
2021-11-29 14:16:51,473 - WARNING: Executing  wait_for= created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:337> took 0.004 seconds
2021-11-29 14:16:51,521 - WARNING: Executing , None) at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/futures.py:308 created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:605> took 0.003 seconds
2021-11-29 14:16:51,521 -    INFO: selfish sleeping
2021-11-29 14:16:55,526 -    INFO: done sleeping
2021-11-29 14:16:55,526 - WARNING: Executing  wait_for= wait_for= cb=[Task.task_wakeup()] created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:337> cb=[_run_until_complete_cb() at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/base_events.py:184] created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 4.005 seconds
2021-11-29 14:16:55,531 - WARNING: Executing , None) at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/futures.py:308 created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:605> took 0.004 seconds
2021-11-29 14:16:55,535 - WARNING: Executing  exception=TimeoutError('timeout!') created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:337> took 0.004 seconds
2021-11-29 14:16:55,539 - WARNING: Executing  exception=TimeoutError('timeout!') created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 0.003 seconds
2021-11-29 14:16:55,548 - WARNING: Executing  result=None created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 0.003 seconds
2021-11-29 14:16:55,555 - WARNING: Executing  result=None created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 0.002 seconds
2021-11-29 14:16:55,560 -   DEBUG: Close <_UnixSelectorEventLoop running=False closed=False debug=True>
Traceback (most recent call last):
  File "/mnt/c/Users/me/Documents/mydir/selfish.py", line 65, in 
    asyncio.run(main(), debug=True)
  File "/home/me/miniconda3/envs/py310/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/me/miniconda3/envs/py310/lib/python3.10/asyncio/base_events.py", line 641, in run_until_complete
    return future.result()
  File "/mnt/c/Users/me/Documents/mydir/selfish.py", line 60, in main
    await timeshare()
  File "/mnt/c/Users/me/Documents/mydir/selfish.py", line 43, in timeshare
    result = await task
  File "/mnt/c/Users/me/Documents/mydir/selfish.py", line 21, in timeout_checker
    raise asyncio.TimeoutError("timeout!")
asyncio.exceptions.TimeoutError: timeout!

where the message showing the excess time is:

2021-11-29 14:16:55,526 - WARNING: Executing  wait_for= wait_for= cb=[Task.task_wakeup()] created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:337> cb=[_run_until_complete_cb() at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/base_events.py:184] created at /home/me/miniconda3/envs/py310/lib/python3.10/asyncio/tasks.py:638> took 4.005 seconds

Seems completely misleading: it seems to say that the time was spent in either main (which is too high level to be useful) or in timeout_checker, which isn't the case. I don't see any hint in that message for which coroutine actually consumed the time.

I'm sure a profiler (e.g., yappi) could find it, but I'm not sure I can use that in the context where the problem is arising. I was hopeful that slow_callback_duration would be sufficient. Am I using it incorrectly or misinterpreting what it's telling me?

how to use slow_callback_duration to find blocking coroutines in asyncio

0 Answers