Debugging `asyncio` execution time warnings when waiting for task wakeups

Async-SIG
,
1

Some prior discussions:

In my application, I have several tasks implementing a so-called worker abstraction that abstract away a long-running task with several smaller tasks underneath it. These workers are primarily handling TCP/IP connections to external devices, but there’s some HTTP and other Ethernet-based protocols as well.

An issue that I am currently dealing with and do not know how to proceed debugging it, much less fixing it, is that a lot of these workers are reporting long execution times when I put asyncio in debug mode with loop.set_debug(enabled=True).

Many of these workers are using asyncio.to_thread because the underlying TCP/IP clients were developed without the use of asyncio streams and are thus synchronous clients. I am almost always suspicious of these clients. However, one of the workers I have is one that simply logs to an InfluxDB OSS 2.0 timeseries database using their official Python client, which exposes an asyncio API. I was surprised to see it pop up in these reports, so now I am questioning something in my worker framework.

The TelemetryWorker mentioned in the warning below does nothing but listen to an asyncio.Queue and then call the following code when a message of a list of data points to log is received:

            success = await self.__write_api.write(
                self.__bucket, self.__org, record=point_or_points
            )

and some basic NamedTuple to dictionary conversions. The self.__write_api is Influx’s WriteApiAsync. So I’m somewhat suspicious that something so core to asyncio would be wrong in their API.

Here is one of the warnings I receive:

Executing <Task pending name='TelemetryWorker' coro=<AsyncWorker.run() running at /control_server/async_core/worker.py:165> wait_for=<Future pending cb=[Task.task_wakeup()] created at /.asdf/installs/python/3.12.2/lib/python3.12/asyncio/base_events.py:448> created at /.asdf/installs/python/3.12.2/lib/python3.12/asyncio/tasks.py:420> took 0.318 seconds

The line of code at /control_server/async_core/worker.py:165 is

await self._receive_message(message)

and this line of code is running inside an asyncio.Task. (Every worker is ran via an asyncio.Task but may have some sub-tasks running for it.) self._receive_message is this

    @override
    async def _receive_message(self, message: TelemetryMessage) -> None:
        match message:
            case data:
                points: list[Point] = [entry.to_point() for entry in data]
                await self.__write(points)

which simply defers down to the self.__write_api.write code snippet I wrote above.

I am at a loss as to why this worker is generating a message of something taking hundreds of milliseconds to execute. My understanding is that the warning means that the entire asyncio event loop is blocked for that time. In other words, maybe it takes some time for the InfluxDB writes to take place (which are over HTTP), but awaiting them shouldn’t block the event loop since they are contained inside an asyncio.Task.

The messages to all workers are received via an asyncio.Queue. The reading is done via the following code, where self.__queue is an asyncio.Queue:

        message = await self.__queue.get()
        self.__queue.task_done()
  1. Are there any smoking guns here?
  2. How can I debug this further?
  3. What does wait_for=<Future pending cb=[Task.task_wakeup()] created at /.asdf/installs/python/3.12.2/lib/python3.12/asyncio/base_events.py:448> mean? That almost sounds like it’s not my code, it’s that waking up a task is taking that long. If that’s the case, then is it perhaps the things getting launched via asyncio.to_thread in the ThreadPoolExecutor bogging down the system by creating overhead switching between all the threads? I imagined that if the asyncio event loop thread is being starved then it could “think” that a coroutine or task is taking that long, when it reality it didn’t, it’s just that the thread was starved from executing. Or does asyncio only time execution time on the asyncio event loop thread itself?