Skip to content

Finding Blocking Calls with asyncio Debug Mode

The symptom is unmistakable once you have seen it: request latency has a heavy tail that no downstream metric explains. The database says 4 ms, the upstream API says 30 ms, CPU sits at 25%, and yet p99 is 900 ms and climbing with load. Nothing is slow — something is blocking. Somewhere in the request path a synchronous call is running on the event loop thread, and while it runs every other connection, timer, and callback is frozen behind it. The offender is rarely dramatic: a json.loads() on a 4 MB payload, a requests.get() that survived a migration, a Jinja render, socket.getaddrinfo() resolving a hostname, or a lazily imported module that reads from disk on first use.

Debug mode is the fastest way to name that call. Turn it on, lower the slow-callback threshold to something near your latency budget, and asyncio will log every callback that overruns it, with the source location of the coroutine that was running. This guide walks the full loop: reproducing the stall, enabling debug mode, reading the warning, confirming the culprit when the warning points at framework code, fixing it with the right offload, and proving the fix with the same measurement that found it.

Prerequisites

What a blocking call does to everyone else Four lifelines — two requests, the loop and a timer — with the loop occupied by a 400 ms parse. What a blocking call does to everyone else request A event loop request B timer handler starts json.loads(4 MB) — 400 ms socket readable, ignored timeout due, not fired response, 400 ms late While one callback runs, readable sockets and expired timers simply wait.

1. Reproduce the stall with a measurable signal

Before instrumenting, get a number that moves. The cheapest is a lag probe running alongside your workload: a coroutine that sleeps a fixed interval and reports how much longer it actually took. If a blocking call exists, the probe's overshoot is the length of that call.

import asyncio
import time


async def lag_probe(interval: float = 0.1) -> None:
    loop = asyncio.get_running_loop()
    worst = 0.0
    while True:
        t0 = loop.time()
        await asyncio.sleep(interval)
        lag = loop.time() - t0 - interval
        if lag > worst:
            worst = lag
            print(f"new worst loop lag: {lag * 1000:.1f} ms at {time.strftime('%H:%M:%S')}")

Run it with your load test. A healthy loop reports sub-millisecond values. Verify: you see worst-case lag in the tens or hundreds of milliseconds — that is the blocking call, and its magnitude tells you what threshold to use in the next step. If lag stays under a millisecond while latency is still bad, you do not have a blocking problem; look at concurrency limits and downstream timings instead.

2. Enable debug mode and lower the threshold

Debug mode makes asyncio time every callback and log the ones that overrun loop.slow_callback_duration (default 0.1 s). Set the threshold just below the lag you measured, so the log names the offender rather than drowning you in noise.

import asyncio
import logging

logging.basicConfig(level=logging.WARNING,
                    format="%(asctime)s %(levelname)s %(name)s %(message)s")


async def main() -> None:
    loop = asyncio.get_running_loop()
    loop.slow_callback_duration = 0.05          # start at 50 ms, tighten later
    await run_workload()


asyncio.run(main(), debug=True)

Two equivalent switches exist and are worth knowing: PYTHONASYNCIODEBUG=1 in the environment (useful when you cannot edit the entry point — for example under uvicorn), and loop.set_debug(True) at runtime. Verify: with the workload running, WARNING asyncio Executing <Task …> took 0.312 seconds lines appear. If nothing appears while lag is high, the stall is happening outside a callback — most often in a module-level import, a signal handler, or the garbage collector.

3. Read the warning and identify the call

The warning has three parts that matter: the coroutine or callback object, the source location where it was created, and the elapsed time.

WARNING asyncio Executing <Task pending name='Task-42'
  coro=<handle_request() running at /srv/app/api.py:118>
  wait_for=<Future pending>> took 0.474 seconds

running at /srv/app/api.py:118 is the line the coroutine was suspended on (or executing) when the loop regained control — usually within a few lines of the blocking call. Open that frame and look for anything synchronous: a requests/urllib call, open()/read() on a large file, subprocess.run(), a crypt/bcrypt hash, re against a pathological pattern, a pandas transform, or a client library whose "async" API is a thin wrapper over a blocking one.

# api.py:118 — the pattern to look for
async def handle_request(payload: bytes) -> dict:
    doc = json.loads(payload)                 # 4 MB parse: ~400 ms on the loop thread
    profile = requests.get(URL, timeout=2).json()   # blocking HTTP inside a coroutine
    return render(doc, profile)

Verify: comment out the suspect line (return a stub) and re-run. If the warnings and the lag disappear together, you have the right line. This bisection is faster than reasoning about it, and it protects you from fixing a call that was merely adjacent to the real one.

One second of loop time during a stall Three swimlanes over one second, dominated by a single wide blocking segment. One second of loop time during a stall callbacks requests.get() blocks socket reads queued, not polled timers overdue t = 0 s … 1 s of wall clock The wide band is the offender; everything below it is the queue it created.

4. When the warning points at framework code

Sometimes the location is site-packages/uvicorn/protocols/http/httptools_impl.py or similar, because the framework's callback is what overran — your code merely ran inside it. Two techniques narrow it down.

import asyncio
import faulthandler
import signal

faulthandler.register(signal.SIGUSR1, all_threads=True)   # dump stacks on demand


def dump_running_task() -> None:
    """Called from a signal handler: what is the loop executing right now?"""
    for task in asyncio.all_tasks():
        if task.get_coro().cr_frame and task.get_coro().cr_await is None:
            # cr_await is None while the coroutine is actually running, not suspended
            print("running:", task.get_name(), task.get_coro().cr_frame.f_lineno)

The first technique is faulthandler: send SIGUSR1 during the stall and you get a real Python traceback of the thread, which points at the exact frame inside the blocking call. The second is a running-task scan: a suspended coroutine has a cr_await, an executing one does not, so the task without one is the one holding the loop. Verify: the traceback's deepest frame is a synchronous library call — that is your line, regardless of what the asyncio warning named.

5. Fix it: offload, replace, or chunk

There are only three real fixes, and choosing between them is a property of the call, not a preference.

import asyncio
import functools

# (a) short, GIL-releasing, or unavoidable third-party blocking call → a thread
profile = await asyncio.to_thread(sdk.fetch_profile, user_id)

# (b) a native async client exists → replace the library outright
async with httpx.AsyncClient() as client:              # instead of requests
    profile = (await client.get(URL, timeout=2.0)).json()

# (c) pure-Python CPU work that must stay in-process → a process pool
loop = asyncio.get_running_loop()
doc = await loop.run_in_executor(POOL, functools.partial(json.loads, payload))

Use (a) for blocking I/O and short CPU work — see running blocking SDK calls with asyncio.to_thread. Use (b) wherever a maintained async client exists; it is always cheaper than a thread hop. Use (c) for sustained CPU work, where threads only move the GIL contention around — the trade-offs are laid out in CPU-bound task offloading. Verify: after the change, the warning for that call is gone and worst-case lag drops back toward the probe's noise floor.

6. Re-measure and lock the threshold in

Fixing one blocking call usually reveals the next one, because the loop is now fast enough for a smaller stall to matter. Tighten the threshold and repeat until the log is quiet at a value you are happy to defend.

loop.slow_callback_duration = 0.02      # 20 ms: strict enough for a 200 ms SLO

Then keep the threshold in production code permanently. Setting it costs nothing while debug mode is off, so the only change needed during the next incident is a restart with --debug. Verify: run the same load test as in step 1 and compare worst-case lag before and after; a fixed blocking call typically moves p99 lag by an order of magnitude.

Worst-case loop lag before and after the fix Four bars pairing before and after measurements for two blocking calls. Worst-case loop lag before and after the fix before: requests.get inline 474 ms after: httpx AsyncClient 3 ms before: json.loads(4 MB) 396 ms after: run_in_executor 11 ms Measured with the step 1 probe at a 100 ms interval under identical load. A fixed blocking call moves worst-case lag by roughly its own duration.

Verification

  • Warnings are silent at your threshold. With the workload at target load and slow_callback_duration set near your budget, no slow-callback warnings appear.
  • Lag matches the probe's floor. Worst-case loop lag is within a few milliseconds of the probe interval's own jitter, not tens or hundreds of milliseconds.
  • Latency tail follows. The service's p99 improves by roughly the length of the blocking call multiplied by how often it ran — if it does not, there is a second offender still hiding behind the first.

Pitfalls and edge cases

  • Debug mode changes timing. The extra bookkeeping slows everything slightly and can mask or move a race. Use it to find blocking calls, not to validate concurrency correctness.
  • The warning names the coroutine, not the call. running at file:line is where the coroutine was, which may be a few frames above the synchronous call. Trust the faulthandler traceback over the warning when they disagree.
  • First-call costs look like random stalls. A lazy import, a TLS handshake, a DNS lookup, or a JIT warm-up blocks only on the first request per process, so it hides in p999 and disappears under steady load. Look for warnings clustered at process start.
  • to_thread is not free. Each hop costs a thread handoff (tens of microseconds) and consumes a slot in the default executor. Moving a very frequent, very short call into a thread can be slower than leaving it inline.
  • Garbage collection is not a callback. A long gen-2 GC pause raises lag without producing any slow-callback warning. If lag spikes correlate with gc.get_stats() collections, tune GC thresholds rather than hunting for a blocking call.
  • Windows and proactor differences. On the Windows proactor loop, some socket operations complete on a thread pool, so timings differ; reproduce the measurement on the platform you deploy to.

Frequently Asked Questions

How do I turn on asyncio debug mode without changing the code?

Set the environment variable PYTHONASYNCIODEBUG=1 before starting the process. It works for any entry point, including servers you do not control such as uvicorn or gunicorn workers, and enables the same behaviour as asyncio.run(main(), debug=True). To also lower the slow-callback threshold without code changes, set it from an application startup hook, since the threshold is a loop attribute rather than an environment setting.

What is a good value for slow_callback_duration?

Start at 50 ms to catch obvious offenders, then tighten toward a tenth of your request latency budget. For a service with a 200 ms p99 target, 20 ms is a reasonable permanent setting: it is short enough that any callback exceeding it is a genuine risk to the tail, and long enough that ordinary callbacks never trip it.

Why does debug mode report no slow callbacks even though the loop stalls?

The stall is happening outside a callback. Common causes are a long garbage-collection pause, a blocking module-level import triggered lazily, work inside a signal handler, or another thread holding the GIL. Confirm with a lag probe plus faulthandler stacks: if the loop lag rises while no callback is running long, the pause is not something asyncio can attribute to a callback.

Can I leave asyncio debug mode enabled in production?

It is not recommended as a permanent setting: it costs roughly 10-30% throughput and retains coroutine creation tracebacks, increasing memory. Leave slow_callback_duration configured permanently (free when debug mode is off) and enable full debug mode temporarily on one instance when you need attribution.