Skip to content

Event Loop Debugging & Instrumentation

An async service that is "slow" is almost never slow in the way a synchronous service is slow. There is no thread stuck in a syscall you can catch with py-spy, no lock convoy, no obvious hot function in a CPU profile. Instead there is one thread — the event loop — that spends its life alternating between running callbacks and polling the selector, and everything you care about is a property of that alternation: how long a single callback ran, how late a scheduled callback fired, how many tasks were resident when latency spiked. None of it appears in an ordinary application profile, because the cost is not in any one function; it is in the queue that function made everyone else wait in.

This section is about making that alternation observable. It covers the loop's own debug facilities (asyncio debug mode and the slow-callback threshold), the two-line lag probe that turns loop health into a gauge you can alert on, task introspection with asyncio.all_tasks() and task factories, and the exception plumbing — loop.set_exception_handler(), unretrieved-exception warnings — that decides whether a failure reaches your logs or disappears. The parent overview, Asyncio Fundamentals & Event Loop Architecture, covers what the loop is; this section covers how to watch it work and how to tell, in production, which of the four things that can go wrong is actually going wrong.

Scope of this section:

  • Debug mode: what it enables, what it costs, and which parts are safe to leave on in production.
  • Event-loop lag as a first-class metric: measuring it, exporting it, alerting on it.
  • Task introspection: enumerating live tasks, naming them, and finding the ones that never finish.
  • Exception routing: the default handler, unretrieved task exceptions, and structured error logs.
  • Cost control: what each probe costs per loop iteration and what to sample rather than measure.

Architectural principles

  • The loop is a serial resource, so latency is queueing. Every callback that runs long delays every other callback by that amount. Instrumentation must therefore measure delay, not throughput — a loop at 30% CPU can still be missing its deadlines if one callback in a hundred runs for 500 ms.
  • Measure the loop from inside the loop. External probes (an HTTP health check, a sidecar) measure the whole path and cannot distinguish a stalled loop from a slow database. A probe scheduled on the loop measures exactly one thing: the loop's own responsiveness.
  • Debug mode is a diagnostic, not a deployment. It adds per-call overhead, keeps coroutine creation tracebacks alive, and changes timing enough to hide races. Use it in staging and in short, targeted production windows — not as a permanent setting.
  • Every task should be identifiable. An unnamed task in a hang dump is a stack trace with no owner. Naming tasks at creation costs nothing and turns all_tasks() output from noise into an inventory.
  • Silence is the worst failure mode. A task whose exception is never retrieved logs only at garbage-collection time, in a warning most log pipelines drop. An exception handler and a done-callback discipline are what make async failures visible at all.
What each probe can see A stack of five instrumentation layers, each annotated with the question it answers. What each probe can see loop lag probe queueing delay — the loop's own responsiveness slow-callback log which callback ran long, and where task population gauge is work accumulating or draining? exception handler failures that no one awaited task dump (on demand) where every suspended task is parked Four continuous signals plus one on-demand dump cover every async stall.

Execution model: what the loop does between your callbacks

One iteration of the event loop does four things in a fixed order: it computes how long it may block in the selector (the delay until the nearest scheduled timer), it polls the selector for ready file descriptors, it moves any expired timers from the scheduled heap into the ready queue, and then it drains the ready queue by calling each callback in turn. The critical detail for instrumentation is that the last step is not interruptible. While a callback runs, no I/O is polled, no timer fires, and no other task advances — the loop is a single-threaded cooperative scheduler, and a callback that does not return is a scheduler that has stopped. The mechanics of that cycle are covered in event loop configuration; what matters here is which parts of it you can observe.

Two observable quantities follow directly. The first is callback duration: the wall time inside a single callback, which asyncio itself measures when debug mode is on and logs when it exceeds loop.slow_callback_duration. The second is loop lag: the difference between when a callback was scheduled to run and when it actually ran. Lag is the sum of everything that ran ahead of it in the queue, so it captures blocking calls, long callbacks, and simple overload in one number — which is why it makes a better alert than any single-callback metric.

The third quantity, task population, is different in kind: it is a level, not a delay. len(asyncio.all_tasks()) sampled on an interval tells you whether work is accumulating faster than it drains. A steady population with rising lag means individual callbacks got slower; a rising population with flat lag means intake exceeded capacity. That two-by-two is most of production triage, and it comes from two cheap gauges.

One iteration of the event loop A left-to-right pipeline of the four stages of one event loop iteration. One iteration of the event loop compute timeout until next timer poll selector ready file descriptors expire timers heap to ready queue drain ready queue callbacks run — uninterruptible Nothing else advances while the last step runs: a long callback is a stopped scheduler.

Instrumentation catalogue

Debug mode and the slow-callback threshold

Debug mode is enabled with asyncio.run(main(), debug=True), the PYTHONASYNCIODEBUG=1 environment variable, or loop.set_debug(True). It turns on four behaviours: callbacks slower than loop.slow_callback_duration (default 100 ms) are logged with their source location, coroutines that are never awaited raise a warning with the creation traceback, non-threadsafe calls from the wrong thread raise, and selected Future/Task objects keep the traceback of where they were created.

import asyncio
import logging

logging.basicConfig(level=logging.WARNING)


async def main() -> None:
    loop = asyncio.get_running_loop()
    loop.slow_callback_duration = 0.05      # log anything over 50 ms
    await work()


asyncio.run(main(), debug=True)
# WARNING:asyncio:Executing <Task ... work() at app.py:14> took 0.312 seconds

The threshold is the useful knob independently of debug mode: setting slow_callback_duration is cheap, and on a latency-sensitive service a value of 20–50 ms surfaces blocking calls long before users notice. The full workflow for turning those warnings into fixes is in finding blocking calls with asyncio debug mode.

The lag probe

The lag probe is a coroutine that sleeps for a known interval and measures how much longer than that it actually took. The excess is the loop's queueing delay at that moment.

import asyncio
import time


async def lag_probe(interval: float = 0.25) -> None:
    loop = asyncio.get_running_loop()
    while True:
        start = loop.time()
        await asyncio.sleep(interval)
        lag = loop.time() - start - interval
        LOOP_LAG.observe(lag)               # histogram, seconds
        if lag > 0.5:
            logging.warning("event loop lag %.3fs", lag)

It costs one task and one timer per interval, which is negligible, and it is the single most valuable async metric you can export. Percentiles matter more than the mean: a p99 lag of 400 ms with a p50 of 1 ms is one bad callback, not general overload. Sizing, alert thresholds, and how to read the histogram are covered in measuring event loop lag in production.

Task introspection

asyncio.all_tasks() returns the set of tasks that are not yet done for the running loop. Combined with Task.get_name() and Task.get_coro(), it is a live inventory of what the service is doing.

import asyncio


def dump_tasks() -> None:
    for task in sorted(asyncio.all_tasks(), key=lambda t: t.get_name()):
        coro = task.get_coro()
        frame = getattr(coro, "cr_frame", None)
        where = f"{frame.f_code.co_filename}:{frame.f_lineno}" if frame else "?"
        print(f"{task.get_name():<28} {coro.__qualname__:<30} {where}")

Printing the current frame of each coroutine tells you where every suspended task is parked — which is exactly the information a hang investigation needs. Wiring this to a signal handler so you can dump it from a running container is described in inspecting pending tasks with asyncio.all_tasks.

Task factories for automatic naming and tracing

A task factory intercepts every task creation on the loop, which is the one place you can attach context — a request id, a trace span, a creation traceback — without touching call sites.

import asyncio
import contextvars

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")


def tracing_task_factory(loop, coro, *, context=None, **kwargs):
    task = asyncio.Task(coro, loop=loop, context=context, **kwargs)
    task.set_name(f"{coro.__qualname__}#{request_id.get()}")
    TASKS_CREATED.inc()
    return task


loop = asyncio.get_event_loop()
loop.set_task_factory(tracing_task_factory)

Every task now carries the request that created it, so a task dump during an incident groups cleanly by request. The factory runs on the hot path, so keep it to attribute assignment — no logging, no I/O.

The exception handler

Exceptions that escape a callback, or that are never retrieved from a task, go to the loop's exception handler. The default prints to stderr; replacing it routes those events into structured logging and your error tracker.

import asyncio
import logging


def handle_exception(loop, context: dict) -> None:
    exc = context.get("exception")
    task = context.get("future")
    logging.error(
        "asyncio error: %s",
        context["message"],
        exc_info=exc,
        extra={"task": task.get_name() if hasattr(task, "get_name") else None},
    )


asyncio.get_event_loop().set_exception_handler(handle_exception)

This is the difference between a background task dying silently at 03:00 and a page firing. Note that it catches unhandled callback errors and unretrieved task exceptions — errors you await and handle yourself never reach it, and errors inside a TaskGroup surface as an ExceptionGroup at the group's exit instead.

Which probe answers which question A five-row matrix of instrumentation mechanisms against signal, cadence, and the question answered. Which probe answers which question signal cadence answers debug mode callback duration staging windows which line blocks lag probe queueing delay continuous is the loop behind? all_tasks() gauge task population every 10 s is work draining? task factory task identity per task who created this? exception handler unhandled errors on failure what died silently? Five mechanisms, five distinct questions — none of them substitutes for another.

Resource boundaries: what each probe costs

Instrumentation runs on the same single thread as the work, so its cost is not free capacity — it is latency. The table below is the budget to reason with; measure on your own hardware before adopting anything in the "continuous" column at high frequency.

Probe Typical cost Safe cadence Notes
slow_callback_duration threshold one perf_counter() pair per callback in debug mode only continuous in staging Zero cost when debug mode is off
Full debug mode 10–30% throughput, plus retained tracebacks short windows Also changes timing; can mask races
Lag probe at 250 ms one timer + one wakeup per interval continuous Cheapest high-value signal
len(all_tasks()) gauge O(number of tasks) set construction every 5–15 s At 50k tasks this is milliseconds — do not sample it per request
Full task dump with frames O(tasks) plus frame formatting on demand only Signal-triggered, never on a timer
Task factory attribute tagging a few hundred nanoseconds per task continuous Keep it allocation-light

The rule of thumb: continuous probes must be O(1) per interval, and anything O(tasks) is on-demand or sampled at tens of seconds. A monitoring loop that walks every task each second will itself become the slow callback it was meant to find.

Relative cost per interval (log-ish scale, illustrative) Horizontal bars showing relative cost of each probe, with the task dump far larger than the rest. Relative cost per interval (log-ish scale, illustrative) lag probe @ 250 ms ~1 unit population gauge @ 10 s ~6 units (O(tasks)) task factory tagging ~2 units per task full debug mode ~40 units (10-30% throughput) task dump with frames ~120 units — on demand only Units are relative to one lag-probe wakeup on a 4-core container running 5k tasks. Continuous probes must be O(1) per interval; anything O(tasks) is sampled or on demand.

Integrated production example

The following service wires all five mechanisms together: a task factory that names and counts tasks, a lag probe exporting a histogram, a periodic population gauge, a structured exception handler, and a SIGUSR1 handler that dumps the live task inventory on demand. It uses stdlib only; the metric objects are stubs you would replace with your Prometheus/OpenTelemetry client.

import asyncio
import contextvars
import logging
import signal
import sys
import time

log = logging.getLogger("service")
request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")


class Gauge:                                   # stand-in for a real metrics client
    def __init__(self, name: str) -> None:
        self.name, self.value = name, 0.0

    def set(self, v: float) -> None:
        self.value = v

    def observe(self, v: float) -> None:
        self.value = v


LOOP_LAG = Gauge("event_loop_lag_seconds")
TASK_COUNT = Gauge("event_loop_tasks")


def tracing_task_factory(loop, coro, *, context=None, **kwargs):
    task = asyncio.Task(coro, loop=loop, context=context, **kwargs)
    task.set_name(f"{getattr(coro, '__qualname__', 'task')}#{request_id.get()}")
    return task


def handle_exception(loop, context: dict) -> None:
    fut = context.get("future")
    log.error("asyncio: %s", context["message"], exc_info=context.get("exception"),
              extra={"task": getattr(fut, "get_name", lambda: None)()})


async def lag_probe(interval: float = 0.25, warn_at: float = 0.25) -> None:
    loop = asyncio.get_running_loop()
    while True:
        start = loop.time()
        await asyncio.sleep(interval)
        lag = loop.time() - start - interval
        LOOP_LAG.observe(max(lag, 0.0))
        if lag > warn_at:                      # one bad callback, not general load
            log.warning("loop lag %.3fs — a callback is running long", lag)


async def population_probe(interval: float = 10.0) -> None:
    while True:
        TASK_COUNT.set(len(asyncio.all_tasks()))
        await asyncio.sleep(interval)


def dump_tasks() -> None:
    tasks = sorted(asyncio.all_tasks(), key=lambda t: t.get_name())
    log.warning("task dump: %d live task(s)", len(tasks))
    for task in tasks:
        coro = task.get_coro()
        frame = getattr(coro, "cr_frame", None)
        where = f"{frame.f_code.co_filename}:{frame.f_lineno}" if frame else "<no frame>"
        log.warning("  %-30s %s", task.get_name(), where)


async def main() -> None:
    loop = asyncio.get_running_loop()
    loop.set_task_factory(tracing_task_factory)
    loop.set_exception_handler(handle_exception)
    loop.slow_callback_duration = 0.05          # 50 ms, well under our SLO
    loop.add_signal_handler(signal.SIGUSR1, dump_tasks)

    async with asyncio.TaskGroup() as tg:
        tg.create_task(lag_probe(), name="probe.lag")
        tg.create_task(population_probe(), name="probe.population")
        tg.create_task(serve(), name="server")


async def serve() -> None:
    while True:                                 # stand-in for the real workload
        await asyncio.sleep(1.0)


if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO, stream=sys.stdout,
                        format="%(asctime)s %(levelname)s %(message)s")
    asyncio.run(main(), debug="--debug" in sys.argv)

Three deliberate choices are worth calling out. The probes live in the same TaskGroup as the server, so if a probe crashes the service notices instead of silently losing observability. slow_callback_duration is set unconditionally — it is free when debug mode is off, and it makes the one-line switch to --debug immediately useful. And the signal handler is installed with loop.add_signal_handler() rather than signal.signal(), so the dump runs on the loop, where all_tasks() is meaningful, instead of in a signal context that can interrupt a callback mid-update.

Diagnostic Hook — four numbers that classify any async stall

Export loop lag (p50/p99, from the probe), live task count, slow-callback warnings per minute, and unhandled-exception events per minute. The combination classifies almost every incident without a profiler: lag p99 up with a flat task count is a single long callback (find it with debug mode); task count climbing with flat lag is intake exceeding capacity (add backpressure); both climbing is saturation; and exceptions rising with flat lag is a failing dependency, not a loop problem. Alert on lag p99 above roughly a tenth of your request SLO, and on any sustained growth in task count.

Triage from two gauges A decision diamond on task-count growth with three outcome cards. Triage from two gauges Is the task count growing? no, flat one long callback lag p99 spikes yes, with flat lag intake exceeds capacity add backpressure yes, with rising lag saturation shed load or scale out Loop lag and task count together classify a stall before you reach for a profiler.

Failure modes

Failure mode Root cause Detection Fix
Latency spikes with low CPU A blocking call (file read, DNS, requests) inside a coroutine Slow-callback warnings; lag p99 far above p50 Offload with asyncio.to_thread or use an async client
Background task dies silently Exception in a fire-and-forget task, never retrieved Nothing in logs; work simply stops Install an exception handler; keep a strong reference to the task
Task count grows without bound Tasks created per event but never awaited or cancelled all_tasks() gauge climbs monotonically; RSS follows Bound creation, use a TaskGroup, cancel on shutdown
Debug mode "fixes" a race Extra bookkeeping changes timing enough to hide the bug The bug reproduces only in production Reproduce with lag/task metrics instead; do not ship debug mode
Monitoring itself stalls the loop An O(tasks) probe on a short timer, or logging inside the task factory Lag correlates with the probe's interval Move to on-demand dumps; sample population at 10 s+
No task names in a hang dump Tasks created without name= and no task factory Dump shows a wall of Task-137 entries Set a task factory that names tasks from context

Frequently Asked Questions

Is it safe to run asyncio debug mode in production?

Full debug mode costs roughly 10-30% throughput and retains coroutine creation tracebacks, so it is not a permanent production setting. What is safe permanently is setting loop.slow_callback_duration, which costs nothing when debug mode is off, plus a lag probe and a task-count gauge. Enable full debug mode in staging, or in a short, deliberately scoped production window on one instance.

What is event loop lag and what value should alert?

Lag is the extra time beyond its scheduled delay that a callback waits before running - the queueing delay of the loop. Measure it with a coroutine that sleeps a known interval and reports the overshoot. Alert on the p99, not the mean, and set the threshold at roughly a tenth of your request latency SLO; for a 200 ms SLO, a sustained p99 lag above 20 ms means the loop is already the bottleneck.

Why does my background task disappear without any error?

Two causes, often together. If nothing holds a reference to the task, it can be garbage collected mid-flight; and if the task raises and no one ever awaits it, the exception is only reported when the task object is finalised, in a warning many log pipelines drop. Keep a strong reference (or use a TaskGroup) and install loop.set_exception_handler() so unretrieved exceptions are logged as errors.

How do I find which coroutine is blocking the event loop?

Enable debug mode and lower loop.slow_callback_duration to about 50 ms. Every callback exceeding it is logged with its source location, which usually names the offending call directly. If the warning points at a framework frame rather than your code, take a task dump at the moment of the stall and look for the task whose current frame sits on a synchronous call.

Does asyncio.all_tasks() include tasks from other event loops?

No. It returns only the not-yet-done tasks belonging to the running loop (or the loop passed explicitly). Tasks on a loop in another thread are invisible to it, which is why a service that runs a second loop in a worker thread needs its own probe inside that thread rather than a single global gauge.