Skip to content

Tracing Slow Callbacks in Production

In staging, asyncio debug mode with loop.slow_callback_duration points straight at the synchronous call that froze the loop. In production, the same stall shows up only as a spike on the loop-lag histogram at 03:12, and nobody is willing to enable debug mode on a fleet to catch the next one — it multiplies per-callback overhead and records a creation traceback for every coroutine. What production needs is a detector cheap enough to leave on permanently that, at the moment the loop is stuck, records what it is stuck on. Two techniques deliver that: a watchdog thread that notices the loop has stopped making progress and captures the loop thread's current Python stack, and a thin timing wrapper around callback execution that names the callback or task that ran too long. This guide measures their overhead against debug mode, builds both, attributes stalls to named tasks, and turns the reports into alerts.

Prerequisites

Per-callback cost of each detector 3 bars comparing baseline with the others. Per-callback cost of each detector baseline 1.27 µs timing wrapper (step 3) 1.31 µs asyncio debug mode 16.7 µs Measured with the step 1 benchmark: 300,000 chained call_soon callbacks. The wrapper costs about 3%; debug mode costs about thirteen times.

1. Measure what debug mode would cost

Before building anything, quantify the overhead that rules debug mode out. A benchmark that runs 300,000 trivial callbacks measures per-callback cost under three configurations.

import asyncio
import functools
import time

N = 300_000


async def run_callbacks() -> float:
    loop = asyncio.get_running_loop()
    done = loop.create_future()
    count = 0

    def callback() -> None:
        nonlocal count
        count += 1
        if count == N:
            done.set_result(None)
        else:
            loop.call_soon(callback)

    started = time.perf_counter()
    loop.call_soon(callback)
    await done
    return time.perf_counter() - started


def per_callback(label: str, debug: bool = False) -> None:
    elapsed = asyncio.run(run_callbacks(), debug=debug)
    print(f"{label:>18}: {elapsed * 1e6 / N:.2f} µs per callback")


per_callback("baseline")
per_callback("debug mode", debug=True)

On Python 3.14 the baseline measured 1.27 µs per callback and debug mode 16.7 µs — roughly thirteen times slower for callback dispatch, before counting the memory for coroutine origin tracking. The timing wrapper from step 3 measured 1.31 µs, about 3% over baseline, which is overhead a service can carry permanently.

Verify: debug mode's per-callback cost is an order of magnitude above baseline on your hardware; that ratio is the argument for the production approach.

2. Capture the blocking stack with a watchdog thread

A stalled loop cannot report on itself, but another thread can. A heartbeat task on the loop records a timestamp every few milliseconds; a watchdog thread checks that timestamp, and when it is too old, reads the loop thread's current frame with sys._current_frames() — while the blocking call is still running.

import asyncio
import sys
import threading
import time
import traceback


class StallWatchdog:
    def __init__(self, threshold: float = 0.2, check_every: float = 0.05) -> None:
        self.threshold = threshold
        self.check_every = check_every
        self.last_beat = time.monotonic()
        self.loop_thread_id = threading.get_ident()      # construct on the loop thread
        self.reports: list[tuple[float, str]] = []
        self._stop = threading.Event()

    async def heartbeat(self) -> None:
        while True:
            self.last_beat = time.monotonic()
            await asyncio.sleep(self.check_every / 2)

    def _watch(self) -> None:
        reported_beat = None
        while not self._stop.wait(self.check_every):
            stalled_for = time.monotonic() - self.last_beat
            if stalled_for > self.threshold and reported_beat != self.last_beat:
                frame = sys._current_frames().get(self.loop_thread_id)
                stack = "".join(traceback.format_stack(frame, limit=10)) if frame else "<no frame>"
                self.reports.append((round(stalled_for, 2), stack))
                reported_beat = self.last_beat           # one report per stall

    def start(self) -> asyncio.Task:
        threading.Thread(target=self._watch, name="loop-watchdog", daemon=True).start()
        return asyncio.create_task(self.heartbeat(), name="watchdog.heartbeat")

    def stop(self) -> None:
        self._stop.set()


def parse_legacy_report() -> None:
    time.sleep(0.4)                                      # the synchronous call that stalls the loop


async def main() -> None:
    watchdog = StallWatchdog(threshold=0.2)
    heartbeat = watchdog.start()
    await asyncio.sleep(0.1)
    parse_legacy_report()
    await asyncio.sleep(0.2)
    watchdog.stop()
    heartbeat.cancel()
    for stalled_for, stack in watchdog.reports:
        print(f"stalled {stalled_for}s at:")
        print("\n".join(stack.strip().splitlines()[-2:]))


asyncio.run(main())

The report arrived about 0.23 seconds into the stall, while parse_legacy_report() was still sleeping, and its innermost frames name exactly that function and the time.sleep line. The watchdog costs one heartbeat timer on the loop and one thread waking a few times per second. Because it samples the stack during the stall, it sees the culprit even when the call is deep inside a third-party library.

Verify: one report is recorded, its last two lines point at parse_legacy_report and time.sleep(0.4), and a run without the blocking call records nothing.

3. Time callbacks cheaply to name the slow one

The watchdog identifies long stalls; a timing wrapper catches every callback above a smaller threshold and names it. On CPython the event loop runs every scheduled callback — including every task step — through asyncio.events.Handle._run, so wrapping that method times them all.

import asyncio
import functools
import time

SLOW: list[tuple[float, str]] = []
_original_run = asyncio.events.Handle._run


def install_callback_timer(threshold: float = 0.05) -> None:
    @functools.wraps(_original_run)
    def timed_run(self):
        started = time.perf_counter()
        try:
            return _original_run(self)
        finally:
            elapsed = time.perf_counter() - started
            if elapsed >= threshold:
                SLOW.append((round(elapsed, 3), describe(self)))

    asyncio.events.Handle._run = timed_run


def describe(handle: asyncio.Handle) -> str:
    callback = handle._callback
    owner = getattr(callback, "__self__", None)          # task steps are bound Task methods
    if isinstance(owner, asyncio.Task):
        return f"task {owner.get_name()}"
    return getattr(callback, "__qualname__", repr(callback))


async def render_invoice() -> None:
    await asyncio.sleep(0)
    time.sleep(0.08)                                      # blocking inside a task step


async def main() -> None:
    install_callback_timer(threshold=0.05)
    asyncio.get_running_loop().call_soon(time.sleep, 0.06)   # blocking plain callback
    await asyncio.create_task(render_invoice(), name="invoice.render:4411")
    print(SLOW)


asyncio.run(main())

Both offenders are reported with a name: the plain sleep callback and the task step of invoice.render:4411. Task names chosen as in naming and tracking tasks for observability are what make the second report actionable. Handle._run is private: loops with their own C implementation, such as uvloop, do not call it, and its internals can change between Python releases, so guard the installation with a version check and a test.

Verify: the list contains two entries, one naming sleep at about 0.06 s and one naming task invoice.render:4411 at about 0.08 s.

Two detectors, two questions 3 stacked layers from Watchdog thread to Reporter. Two detectors, two questions Watchdog thread heartbeat age check sys._current_frames stack during the stall Callback timer wraps Handle._run names task or callback low threshold Reporter counter by kind stall histogram rate-limited stacks The watchdog says where the loop is stuck; the timer says who held it.

4. Turn reports into metrics and rate-limited logs

Raw reports are useful in an incident; operations need aggregates. Export a counter of slow callbacks by name, a histogram of stall durations, and log full stacks at a bounded rate so a pathological stall cannot flood the log pipeline.

import collections
import logging
import time

log = logging.getLogger("loop.stalls")


class StallReporter:
    def __init__(self, max_logs_per_minute: int = 5) -> None:
        self.by_name: collections.Counter[str] = collections.Counter()
        self.durations: list[float] = []
        self._log_times: collections.deque[float] = collections.deque()
        self._max = max_logs_per_minute

    def record(self, name: str, seconds: float, stack: str | None = None) -> None:
        self.by_name[name] += 1                           # export as a labelled counter
        self.durations.append(seconds)                    # export as a histogram
        now = time.monotonic()
        while self._log_times and now - self._log_times[0] > 60:
            self._log_times.popleft()
        if len(self._log_times) < self._max:
            self._log_times.append(now)
            log.warning("event loop stalled %.3fs in %s\n%s", seconds, name, stack or "")


reporter = StallReporter(max_logs_per_minute=2)
for i in range(10):
    reporter.record("task invoice.render", 0.08 + i / 1000, stack="  File ... time.sleep(0.08)")
print(reporter.by_name, "logged:", len(reporter._log_times))

Label the counter by task kind, not full name, to keep cardinality bounded. The histogram of stall durations answers a different question from loop lag: lag says how late timers fired; stall duration says how long single callbacks held the loop, and the two together separate "one slow callback" from "too many small ones". Prometheus wiring is covered in exporting Prometheus metrics from asyncio.

Verify: ten records produce a count of ten for the name but only two log lines within the minute.

5. Set thresholds and alerts from the latency budget

Thresholds should come from what a stall costs users, not from round numbers. If the service's p99 budget is 250 ms, a 100 ms stall consumes 40% of it for every request in flight. Tie the watchdog and timer thresholds to that budget, and alert on rate rather than on single events.

from dataclasses import dataclass


@dataclass(frozen=True)
class StallPolicy:
    p99_budget_s: float

    @property
    def callback_threshold(self) -> float:            # timing wrapper: catch contributors
        return self.p99_budget_s * 0.1

    @property
    def watchdog_threshold(self) -> float:            # watchdog: capture stacks for real stalls
        return self.p99_budget_s * 0.4

    def should_alert(self, stalls_last_5m: int, requests_last_5m: int) -> bool:
        return requests_last_5m > 0 and stalls_last_5m / requests_last_5m > 0.001


policy = StallPolicy(p99_budget_s=0.25)
print(policy.callback_threshold, policy.watchdog_threshold)            # 0.025 0.1
print(policy.should_alert(stalls_last_5m=12, requests_last_5m=6000))   # True: 0.2% of requests

A low callback threshold collects many small offenders cheaply; a higher watchdog threshold keeps stack capture rare. Alerting on stalls per request normalises for traffic, so a quiet night and a busy peak use the same rule. When the reports point at CPU-heavy work rather than a blocking call, move it off the loop following CPU-bound task offloading.

Verify: the thresholds derive from the budget, and the alert fires at a stall rate above one per thousand requests.

How the watchdog catches a stall in progress 3 lanes over time. How the watchdog catches a stall in progress loop thread heartbeats blocked in time.sleep resumes heartbeat age growing over threshold watchdog capture stack time → The capture happens during the stall, so the culprit is still on the stack.

Verification

Production stall tracing is in place when:

  • It is always on: the watchdog and callback timer run in production with overhead measured in single-digit percent.
  • Stalls come with stacks: each stall above the watchdog threshold produces a stack captured during the stall.
  • Slow callbacks come with names: timing reports name the task kind or callback, not Handle objects.
  • Output is bounded: counters and histograms are exported, and stack logs are rate-limited.
  • Alerts are budget-based: thresholds derive from the latency budget, and alerts use stall rate per request.

Pitfalls & edge cases

  • Watchdog constructed on the wrong thread. threading.get_ident() must be read on the loop thread; constructing the watchdog elsewhere samples the wrong thread's stack.
  • Stacks that show only select. A report pointing at the selector means the loop was idle, not stalled — usually the heartbeat itself was delayed by a stalled previous iteration. Lower check_every so sampling catches the stall in progress.
  • Alternative loop implementations. uvloop runs callbacks in C and bypasses Handle._run; the watchdog still works, the timing wrapper does not.
  • GIL contention masquerading as stalls. CPU-heavy threads can delay the loop thread without any slow callback on it. If the captured stack shows ordinary code, check thread activity with py-spy.
  • Capturing stacks with locals. Formatting frame locals can serialise secrets into logs. Capture code locations only.

Frequently Asked Questions

Can I use asyncio debug mode in production?

It is usually too expensive. In our benchmark, debug mode made callback dispatch about thirteen times slower, and it also tracks where every coroutine was created. Keep it for development and staging, and use a watchdog thread plus lightweight callback timing to detect slow callbacks in production.

How do I find which code blocked the asyncio event loop in production?

Run a heartbeat coroutine that records a timestamp and a separate watchdog thread that checks it. When the timestamp is older than a threshold, the watchdog reads the event loop thread's current frame with sys._current_frames and formats the stack, capturing the blocking call while it is still running.

Does loop.slow_callback_duration work without debug mode?

No. The slow callback warnings controlled by slow_callback_duration are only emitted when the loop runs in debug mode. Without debug mode, time callback execution yourself, for example by wrapping callback execution, or detect stalls externally with a watchdog thread.

What threshold should I use for slow asyncio callbacks?

Derive it from your latency budget. A stall delays every request in flight, so a callback threshold around a tenth of the p99 budget catches meaningful contributors, and a stack-capturing watchdog threshold around a third to half of the budget keeps captures rare. Alert on stalls per request rather than on individual stalls.