Skip to content

Tracing Awaits with sys.monitoring

A coroutine that takes 75 ms of wall time might spend it waiting on any of its awaits, and ordinary profilers do not say which: they count CPU time, and a suspended coroutine uses none. Python 3.12's sys.monitoring exposes the two events that bracket a suspension — PY_YIELD when a coroutine frame gives up control and PY_RESUME when it continues — so the time between them, keyed by the line of the await, is exactly how long that await kept the coroutine waiting. Measured on Python 3.14 with a handler awaiting a cache lookup (2 ms), a database query (20 ms) and an HTTP call (50 ms), run 200 times with 50 in flight: the tracer attributed a mean of 50.7 ms to the HTTP line, 20.5 ms to the database line and 2.4 ms to the cache line — the delays each call was built with, plus scheduling. Enabling the two events globally slowed a tiny task from 9.17 µs to 20.05 µs; enabling them only on the handler's code object kept it at 11.68 µs. This guide builds that tracer.

Prerequisites

1. Understand what PY_YIELD and PY_RESUME measure

When a coroutine reaches an await on something that is not ready, its frame suspends — a PY_YIELD event — and control returns to the event loop. When the awaited thing completes, the task steps the coroutine again and the frame continues — a PY_RESUME event. The interval between the two on the same frame is wall time the coroutine spent waiting at that line:

import sys

mon = sys.monitoring
TOOL = 3                                     # tool IDs 0-5; pick one no other tool uses

def on_yield(code, offset, retval):
    frame = sys._getframe(1)                 # the coroutine frame that is suspending
    ...

def on_resume(code, offset):
    frame = sys._getframe(1)                 # the same frame, continuing
    ...

Two details matter. A suspension propagates through the whole await chain — a handler awaiting db(), which awaits asyncio.sleep, yields in every frame of the chain — so the same wait is visible at each level, and scoping the events to the functions you care about (step 3) keeps the report readable. And PY_RESUME also fires when a coroutine starts for the first time, with no preceding yield, so the handler must ignore resumes it has no matching yield for.

Verify: a coroutine with one await asyncio.sleep(0.05) reports one suspension of about 50 ms at that line.

2. Build a tracer keyed by function and line

Record the frame's identity, function and current line at each yield, and accumulate the elapsed time at the matching resume:

import time
from collections import defaultdict

class AwaitTracer:
    def __init__(self, tool: int = 3):
        self.tool = tool
        self.suspended = {}                                  # id(frame) -> (key, t0)
        self.wait = defaultdict(float)
        self.count = defaultdict(int)

    def on_yield(self, code, offset, retval):
        frame = sys._getframe(1)
        self.suspended[id(frame)] = ((code.co_qualname, frame.f_lineno), time.perf_counter())

    def on_resume(self, code, offset):
        entry = self.suspended.pop(id(sys._getframe(1)), None)
        if entry:
            key, t0 = entry
            self.wait[key] += time.perf_counter() - t0
            self.count[key] += 1

    def start(self, codes):
        mon.use_tool_id(self.tool, "await-tracer")
        mon.register_callback(self.tool, mon.events.PY_YIELD, self.on_yield)
        mon.register_callback(self.tool, mon.events.PY_RESUME, self.on_resume)
        for code in codes:
            mon.set_local_events(self.tool, code, mon.events.PY_YIELD | mon.events.PY_RESUME)

    def stop(self, codes):
        for code in codes:
            mon.set_local_events(self.tool, code, 0)
        mon.register_callback(self.tool, mon.events.PY_YIELD, None)
        mon.register_callback(self.tool, mon.events.PY_RESUME, None)
        mon.free_tool_id(self.tool)

Measured on a handler with three awaits, 200 requests: line 40 (await http()) 200 suspensions, mean 50.7 ms; line 39 (await db()) mean 20.5 ms; line 38 (await cache()) mean 2.4 ms. The ranking points straight at the line to optimise, which a CPU profile of the same run could not, since the handler used almost no CPU. Means include time spent waiting for the loop to get round to the task after its result was ready — under load, that scheduling delay is part of what users experience, and comparing it with measuring event loop lag in production separates the two.

Verify: the tracer's totals per line add up to roughly the handler's wall time.

Mean suspension per await line, 200 requests 3 horizontal bars comparing line 40: await http() with the others. Mean suspension per await line, 200 requests line 40: await http() 50.7 ms line 39: await db() 20.5 ms line 38: await cache() 2.4 ms Built with 50, 20 and 2 ms of simulated latency; 50 requests in flight. Wall time attributed to the await that caused it.

3. Scope events to the code you are investigating

sys.monitoring.set_events turns events on for every function in the process; set_local_events turns them on for one code object. The difference in cost is large, because with global events every coroutine suspension in the program — including asyncio's own and every library's — calls back into Python:

codes = [handler.__code__, OrderService.place.__code__]   # what you are investigating
tracer.start(codes)
...
tracer.stop(codes)

Measured with 20,000 tiny tasks that each awaited asyncio.sleep(0) once: 9.17 µs per task with no monitoring, 20.05 µs with PY_YIELD and PY_RESUME enabled globally, 11.68 µs with them enabled only on one function. Real handlers do far more work per await, so the relative overhead in practice is lower, but global events still multiply the cost of every suspension everywhere. Local events also make the output readable, since only the instrumented functions appear. Use code.co_qualname for keys so methods are reported with their class names.

Verify: the tracer instruments only named code objects, and request latency with it enabled is within a few per cent of latency without.

Cost of a tiny task that awaits once A grid of 3 rows by 3 columns. Cost of a tiny task that awaits once monitoring cost per task relative none 9.17 us 1.00x PY_YIELD + PY_RESUME, global 20.05 us 2.19x PY_YIELD + PY_RESUME, one code object 11.68 us 1.27x Python 3.14; 20,000 tasks each awaiting asyncio.sleep(0).

4. Turn it on and off at runtime

Because monitoring is enabled per code object at runtime, the tracer can be switched on for a minute in production without a restart — from an admin endpoint, a signal handler or a management console:

async def trace_for(seconds: float, codes) -> dict:
    tracer = AwaitTracer()
    tracer.start(codes)
    try:
        await asyncio.sleep(seconds)
    finally:
        tracer.stop(codes)
    return {
        f"{name}:{line}": {"count": tracer.count[(name, line)],
                           "mean_ms": tracer.wait[(name, line)] / tracer.count[(name, line)] * 1e3}
        for (name, line) in tracer.wait
    }

Always stop in a finally, and always free the tool ID: a tool ID left in use blocks the next use_tool_id with ValueError, and events left enabled keep costing time. Tool IDs are shared across the process, and debuggers, coverage tools and profilers claim some of them (sys.monitoring.DEBUGGER_ID, COVERAGE_ID, PROFILER_ID, OPTIMIZER_ID); choose an unused one and check with sys.monitoring.get_tool(id) first. A live view of all tasks complements this per-line view, as in inspecting a live loop with aiomonitor.

Verify: after a timed trace, sys.monitoring.get_tool(TOOL) returns None and request latency returns to its baseline.

5. Read the results with the right caveats

The tracer measures where a coroutine waited, not why. A long wait at await db() may be the query, the pool queue in front of it, or the loop being too busy to resume the task — and those have different fixes:

async def db():
    async with pool.acquire() as conn:            # waiting for a connection
        return await conn.fetch(QUERY)            # waiting for the query

Instrument the inner function as well and the wait splits by line: pool acquisition on one line, the query on the next. Waits inside asyncio.gather or a TaskGroup belong to the child tasks, not the parent's await line, which shows only the time until all children finished. And sys._getframe(1) inside the callback is the frame that triggered the event in CPython's current implementation — robust in practice, but an implementation detail worth a test. For CPU-bound slowness rather than waiting, use a sampling profiler, as in profiling asyncio applications with py-spy.

Verify: a long wait has been split down to a single cause — pool, query or scheduling — before acting on it.

Which tool for which slowness? A decision on What does the slow coroutine do with 4 outcomes. Which tool for which slowness? What does the slow coroutine do? waits a lot, little CPU PY_YIELD/PY_RESUME on its code per-line wait one await dominates instrument the awaited function too pool vs query burns CPU sampling profiler not a waiting problem every task slow loop lag probe scheduling, not awaits Local events keep the overhead near 1.3x on the instrumented code only.

Verification

Await tracing is set up well when:

  • Events are enabled per code object, not globally, and only while investigating.
  • Waits are keyed by function and line, and add up to the coroutine's wall time.
  • The tool ID is freed in a finally, and latency returns to baseline afterwards.
  • Long waits are split further before being attributed to a single cause.

Diagnostic Hook: keep a timed trace endpoint in services you operate, restricted to administrators, that instruments a named handler for 30–60 seconds and returns the per-line table. When a latency alert fires, the per-await breakdown from production — not a reproduction on a laptop — is usually what settles which dependency to look at.

Pitfalls & edge cases

  • Global events. Measured: 2.19× the cost of every task in the process.
  • Unmatched resumes. The first resume of a coroutine has no yield; ignore it.
  • Forgetting to free the tool ID. The next use_tool_id fails.
  • Reading wait time as call time. It includes pool queues and scheduling delay.

Frequently Asked Questions

How do I find which await is slow in an asyncio coroutine?

Enable sys.monitoring PY_YIELD and PY_RESUME events on the coroutine's code object and time the interval between a yield and the next resume of the same frame, keyed by line. Three awaits were ranked at 50.7, 20.5 and 2.4 ms in testing.

What does sys.monitoring cost in an asyncio application?

With PY_YIELD and PY_RESUME enabled globally, a tiny task went from 9.17 µs to 20.05 µs; enabled on one function with set_local_events, 11.68 µs.

Why doesn't cProfile show where my coroutine waits?

It measures time in functions while they run; a suspended coroutine is not running. Suspension time only appears between PY_YIELD and PY_RESUME events.

Can I trace awaits in production?

Yes, briefly: enable local events on specific code objects from an admin endpoint, stop them in a finally block, and free the tool ID.