Diagnosing Blocked Event Loops in Production

An asyncio service has a failure mode that looks like everything and nothing: every endpoint slows at the same moment, CPU stays low, every dependency reports healthy, and there is no error anywhere. The cause is a synchronous call running on the loop thread, which stops every coroutine in the process until it returns. This page covers confirming that is what is happening and then finding which call — in staging with debug mode, and in production with a watchdog that captures the loop's stack at the moment of the stall. It is a task article under concurrency and GIL observability, part of the Python profiling and performance observability section.

Prerequisites

pip install "prometheus-client>=0.20.0,<1.0.0"

Everything else used here — asyncio's debug mode, sys._current_frames, traceback — is in the standard library.

Implementation

Step 1 — Confirm the loop is blocked, not busy. Event loop lag high with CPU low is the signature of a synchronous wait on the loop. Lag high with CPU high is genuine computation on the loop, which is a related problem with a different remedy. The first is far more common, and it is also the one an on-CPU profiler cannot see, because the loop thread is waiting rather than executing. Measuring asyncio event loop lag covers the lag metric itself.

Step 2 — Use debug mode in staging to name slow callbacks. Debug mode makes the loop time every callback and log any that exceed a threshold. It names the coroutine directly, which is often enough. The overhead makes it unsuitable for production, and in staging under representative load it is the fastest route to an answer.

import asyncio, logging

logging.basicConfig(level=logging.WARNING)
loop = asyncio.new_event_loop()
loop.set_debug(True)
loop.slow_callback_duration = 0.05        # warn on anything holding the loop > 50 ms
asyncio.set_event_loop(loop)

Expected Output: the loop names the offending task and how long it held the thread.

WARNING:asyncio:Executing <Task pending name='Task-4182' coro=<get_order() running at app/views.py:88>> took 0.312 seconds

Step 3 — Install a watchdog for production. Debug mode is too expensive to leave on. A watchdog thread that checks a heartbeat the loop updates, and captures the loop thread's stack when the heartbeat goes stale, gives the same answer at almost no cost: when the loop is healthy it compares two timestamps, and it does real work only during a stall.

# loop_watchdog.py
import asyncio
import logging
import sys
import threading
import time
import traceback

log = logging.getLogger("loop-watchdog")
_heartbeat = time.monotonic()


async def _beat(interval: float = 0.05) -> None:
    global _heartbeat
    while True:
        _heartbeat = time.monotonic()
        await asyncio.sleep(interval)


def _watch(loop_thread_id: int, threshold: float, check_every: float) -> None:
    last_report = 0.0
    while True:
        time.sleep(check_every)
        stalled_for = time.monotonic() - _heartbeat
        if stalled_for < threshold or time.monotonic() - last_report < 5:
            continue
        # 1. Read the loop thread's CURRENT stack — during the stall, not after.
        frame = sys._current_frames().get(loop_thread_id)
        stack = "".join(traceback.format_stack(frame)) if frame else "<no frame>"
        log.warning("event loop blocked", extra={
            "stalled_ms": round(stalled_for * 1000), "stack": stack})
        last_report = time.monotonic()


def install(loop: asyncio.AbstractEventLoop, threshold: float = 0.1) -> None:
    loop.create_task(_beat())
    loop_thread_id = threading.get_ident()          # call from the loop's thread
    threading.Thread(target=_watch, args=(loop_thread_id, threshold, 0.025),
                     daemon=True, name="loop-watchdog").start()

Expected Output: the stack at the moment of the stall, with the synchronous call at the bottom.

WARNING loop-watchdog event loop blocked stalled_ms=287
  File "app/views.py", line 88, in get_order
    row = legacy_db.fetch_order(order_id)
  File "app/legacy_db.py", line 41, in fetch_order
    cur.execute(SQL, (order_id,))
  File "psycopg2/extensions.py", line ...

Step 4 — Check the usual culprits. Most incidents come from a short list. A synchronous database driver or HTTP client called inside a coroutine is the most common. A logging handler writing synchronously to a slow sink is the second, and the most surprising, because the call is a log.info that nobody suspects — the fix is in logging from asyncio tasks without blocking. Large JSON encoding or decoding, blocking DNS resolution in a library that does its own, and CPU-heavy work such as templating or compression make up most of the rest.

Step 5 — Move the call off the loop and confirm. A synchronous call that cannot be replaced with an async equivalent can run in a thread, which frees the loop while it waits. The confirmation is the lag distribution returning to its normal shape, not the absence of watchdog warnings, since a warning threshold can be crossed by smaller stalls that still matter.

import asyncio

async def get_order(order_id: str):
    # The synchronous driver now blocks a worker thread, not the loop.
    return await asyncio.to_thread(legacy_db.fetch_order, order_id)

Step 6 — Keep the watchdog installed. Blocking calls are reintroduced constantly — a new dependency with a synchronous client, a logging change, an innocent-looking library upgrade. A watchdog left running turns the next occurrence into a single log line with a stack, rather than another afternoon of investigation.

Why this is so hard to find without the right tool

Blocked loops persist in production for longer than almost any other performance problem, and the reasons are structural.

Every usual signal points somewhere else. Request latency rises on every endpoint, so no endpoint stands out. Dependencies report healthy, because they are. CPU is low, so nobody suspects the process. Traces show slow spans across unrelated operations, with the time falling in gaps between spans rather than inside any of them — a coroutine waiting for the loop to become free is not inside any instrumented operation.

Profilers mislead by default. An on-CPU profile of a loop blocked on a synchronous socket read shows an almost idle process, because the thread is waiting in the kernel. Only a wall-clock profile, or a stack captured at the moment of the stall, shows the blocking call.

The cause is often innocent-looking. A log.info call, a requests.get for a feature flag, a json.dumps of a large response. None of these looks like a performance problem in review, and all of them block the loop. The watchdog's value is that it names the call regardless of how innocent it looks.

Intermittency hides it. A call that blocks for three hundred milliseconds only when a downstream service is slow, or only for large payloads, produces stalls that come and go with conditions nobody is correlating. Lag percentiles over time, with the watchdog's stacks attached to the spikes, turn an intermittent mystery into a pattern with a named cause.

Preventing the next one

Finding a blocking call is reactive. Three practices catch most of them before they reach production.

Fail tests on slow callbacks. Running the test suite with debug mode enabled and a threshold low enough to catch synchronous I/O — a few tens of milliseconds — turns a blocking call into a failing test. The warning can be escalated to an error with a logging filter, so a pull request that introduces requests.get inside a coroutine fails its checks rather than an on-call engineer's evening.

Review new dependencies for their I/O model. A library that performs network or file I/O either offers an async interface or it does not. Asking the question when the dependency is added is cheaper than discovering the answer from a watchdog stack. Where only a synchronous client exists, wrapping it once in a thin async adapter that uses a thread — and forbidding direct use — keeps the fix in one place.

Treat logging configuration as part of the loop's contract. Every handler attached to the root logger runs on whatever thread logs, and in an async service that is the loop thread. A handler added for a new destination — a network sink, a slow file system, a third-party service — becomes a blocking call on every log statement in the process. Routing all handlers through a queue, so the loop only ever enqueues, removes this category permanently.

Configuration options

Verification

The fix is verified by the lag distribution, not by the absence of warnings.

histogram_quantile(0.99, rate(event_loop_lag_seconds_bucket{service="checkout"}[10m]))

Expected Output: the tail falling back to a few milliseconds after the change.

before  event_loop_lag p99  0.291 s
after   event_loop_lag p99  0.004 s

A tail that improves but does not return to single-digit milliseconds means a second blocking call remains; the watchdog's next warning will name it.

Common mistakes

Investigating the endpoints that spiked. Error signature: hours spent on handlers that turn out to be fine. Root cause: they are victims of a stall elsewhere. Remediation: look for the call holding the loop, which the watchdog names.

Using an on-CPU profile. Error signature: an idle-looking profile of a slow service. Root cause: the loop thread is blocked, not executing. Remediation: capture a stack during the stall, or profile wall-clock.

Leaving debug mode on in production. Error signature: a service slower after the diagnostic change than before. Root cause: debug mode instruments every callback. Remediation: use it in staging, and the watchdog in production.

Capturing the stack after the stall. Error signature: a stack that shows healthy code. Root cause: the capture ran on the loop thread once it was free. Remediation: capture from a separate thread while the loop is still held.

Fixing one call and removing the watchdog. Error signature: the same symptom three months later from a different call. Root cause: blocking calls are reintroduced constantly. Remediation: keep the watchdog installed permanently.

Frequently Asked Questions