Python Observability

Measuring asyncio Event Loop Lag

An asyncio service runs everything on one thread, so anything that occupies that thread delays everything else. Event loop lag is the measurement of that delay, it costs one coroutine and one metric series, and it is the difference between "the service is slow" and "the service is slow because something is blocking the loop". This page covers the sampler, the buckets, and how to get from a lag spike to the call that caused it. It builds on runtime and service metrics, part of the Python metrics and instrumentation section.

What the sampler is actually measuring An event loop timeline with four ready callbacks and one blocking call. The sampler asked to resume at a specific due time, marked on the timeline. Just before that moment a coroutine performs a synchronous operation — a blocking file write — which occupies the single loop thread for eighty milliseconds. During that period the three other callbacks that became ready, belonging to three unrelated requests, cannot run either; they are queued behind the same thread. When the blocking call finishes, the loop runs everything that is due, including the sampler, which observes that it resumed eighty milliseconds later than its due time and records that as lag. The key property drawn out is that the sampler measures a delay it shares with every other ready callback, so a single series describes the whole loop rather than the sampler's own experience of it. one thread, four ready callbacks, one blocking call a synchronous write · 80 ms · the loop is held loop thread the sampler's due time when it actually ran lag = 80 ms — and every other ready callback waited the same 80 ms three unrelated requests, resumed late through no fault of their own why one series describes the whole loop the sampler has no privileged position — it waits in the same queue as everything else, so its delay is everyone's delay
The sampler is not special. It queues behind the same thread as every request, which is exactly why its delay is a measurement of the whole loop.

Prerequisites

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

export LOOP_LAG_INTERVAL=0.1     # seconds between samples

Implementation

Step 1 — Write the sampler. Use the loop's own clock, which is monotonic and is the clock the scheduler uses.

import asyncio
from prometheus_client import Histogram

LOOP_LAG = Histogram(
    "python_asyncio_loop_lag_seconds",
    "Delay between a callback's due time and its execution",
    buckets=(0.0005, 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0),
)

async def monitor_loop_lag(interval: float = 0.1) -> None:
    loop = asyncio.get_running_loop()
    while True:
        due = loop.time() + interval
        await asyncio.sleep(interval)
        LOOP_LAG.observe(max(0.0, loop.time() - due))

loop.time() rather than time.monotonic() matters on some implementations where the loop's clock is what scheduling is measured against. The max(0.0, …) guards against a resume marginally early, which produces a tiny negative that a histogram will reject.

Step 2 — Choose buckets for the stalls you care about. This is where a default latency ladder fails: request-latency buckets typically start at 5 ms, and a 20 ms loop stall is both invisible in such a ladder and very much worth knowing about.

# wrong for this metric: a request-latency ladder
buckets=(0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0)

# right: starts at half a millisecond, because that is the resolution that matters
buckets=(0.0005, 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0)

The bucket-selection reasoning generalises; it is set out in choosing histogram buckets for latency SLOs.

Step 3 — Sample often enough. A stall shorter than the sampling interval is caught only if it happens to overlap a sample. To detect stalls of length S reliably, sample at an interval of S or less.

Sampling interval decides which stalls you can see The same minute of loop activity sampled two ways. Along the timeline are six stalls: four of about thirty milliseconds and two of about two hundred milliseconds. Sampling once per second, the sampler happens to overlap both long stalls and one of the short ones, so the histogram records three events and reports a picture in which short stalls barely exist — and the three it caught are the ones that happened to coincide with a wake-up, which is luck rather than measurement. Sampling every hundred milliseconds, every stall longer than a hundred milliseconds is certain to be caught and the thirty millisecond ones are caught often enough to show as a population rather than as outliers. The trade noted is ten times the wake-ups, which is a few microseconds of work per sample and therefore not a trade at all in practice. six stalls in one minute — how many does the sampler see? the stalls four short (~30 ms) · two long (~200 ms) 1 s interval 3 recorded — and which 3 was luck 100 ms interval every long stall certain, the short ones as a population — for ten times a few microseconds
At a one-second interval the three stalls you recorded are the ones that happened to coincide with a wake-up. That is not a measurement.

Step 4 — Alert on a quantile. Lag is near zero the overwhelming majority of the time, so any average is a number that never moves.

# prometheus alerting rule
- alert: EventLoopLagHigh
  expr: histogram_quantile(0.99, sum(rate(python_asyncio_loop_lag_seconds_bucket[5m])) by (le, service)) > 0.05
  for: 10m
  annotations:
    summary: " p99 event loop lag above 50 ms"
    description: "Something is occupying the loop thread. Check for synchronous I/O, CPU-bound work, or a blocking driver."

Step 5 — Find the blocking call. The metric says the loop is being held; debug mode says by what.

import asyncio

async def main() -> None:
    loop = asyncio.get_running_loop()
    loop.set_debug(True)
    loop.slow_callback_duration = 0.02        # 20 ms — staging only
    await serve()

Expected Output:

WARNING asyncio Executing <Task finished coro=<export_report() running at reports.py:88>
        wait_for=<Future finished result=None> created at asyncio/tasks.py:695>
        took 0.412 seconds

That names the coroutine. Debug mode carries its own overhead, so run it in staging under representative load rather than leaving it on in production.

Five ways to block the loop, and where each one shows up Five common causes of event loop lag, grouped by whether they are visible elsewhere. A synchronous database driver used by mistake and a CPU-bound loop inside a coroutine both appear in the timing of the handler that contains them, so a careful look at per-endpoint latency would eventually find them. The other three do not: a synchronous log handler is attributed to whichever request happened to log, a module imported lazily on first use is attributed to the unlucky first request after a deploy, and a long garbage collection pause is attributed to whatever was running when it fired. All five produce loop lag, which is why one series catches the whole category, while per-endpoint latency catches only the first two and attributes the rest to innocent requests — which is how an investigation ends up focused on the wrong endpoint entirely. what blocks a loop, and where the blame lands visible in the handler's own timing too a synchronous database driver · a CPU-bound loop inside a coroutine careful per-endpoint latency review would eventually find these attributed to whichever request was unlucky a synchronous log handler — blamed on whoever logged a module imported on first use — blamed on the first request after a deploy a long GC pause — blamed on whatever was running when it fired one lag series covers all five · per-endpoint latency covers two and points at the wrong endpoint for the other three
The lower group is why this metric exists. Those three are attributed to innocent requests, and an investigation that starts from latency starts in the wrong place.

Configuration options

Option Type Default Recommended
Sampling interval float — 0.1 s
Buckets tuple latency ladder start at 0.0005 s
Clock — time.monotonic loop.time()
loop.set_debug bool False staging only
slow_callback_duration float 0.1 s 0.02 s in staging
Alert statistic — mean p99 over 5 minutes
Labels — none none — it describes the loop

Verification

Prove the metric responds by blocking the loop deliberately.

import asyncio, time

async def main():
    asyncio.create_task(monitor_loop_lag(0.1))
    await asyncio.sleep(1)
    time.sleep(0.3)                            # a deliberate 300 ms block
    await asyncio.sleep(1)

asyncio.run(main())

Expected Output:

python_asyncio_loop_lag_seconds_bucket{le="0.005"} 17.0
python_asyncio_loop_lag_seconds_bucket{le="0.25"} 17.0
python_asyncio_loop_lag_seconds_bucket{le="0.5"} 18.0
python_asyncio_loop_lag_seconds_count 18.0
python_asyncio_loop_lag_seconds_sum 0.318

Seventeen samples under 5 ms and one between 250 and 500 ms — the deliberate block, caught. If every sample lands in the lowest bucket, the sampler is not running; check that the task was created and not garbage-collected, which is the usual cause and is silent.

Then keep an assertion in the test suite for the shape that matters:

async def test_loop_lag_metric_catches_a_block():
    task = asyncio.create_task(monitor_loop_lag(0.01))
    await asyncio.sleep(0.05)
    time.sleep(0.1)
    await asyncio.sleep(0.05)
    task.cancel()
    assert LOOP_LAG.collect()[0].samples[-1].value > 0.05     # the sum moved

Common mistakes

The metric is always zero

Error signature: every sample lands in the smallest bucket, in a service that is demonstrably stalling. Root cause: the monitor task was created and not kept referenced, so it was garbage-collected — a silent failure mode of create_task. Remediation: hold a reference to the task for the process's lifetime, and confirm the sample count rises over time.

Short stalls never appear

Error signature: users report intermittent hesitation; lag looks clean. Root cause: the sampling interval is longer than the stalls. Remediation: sample at or below the duration you want to detect, and start the buckets low enough to resolve it.

Lag is high and no coroutine looks slow

Error signature: lag is consistently above 100 ms and every handler's own timing is fine. Root cause: the blocking work is not in a handler — a synchronous log sink, a module imported at first use, a driver in blocking mode, or garbage collection. Remediation: correlate lag with GC pause duration first, then run debug mode with a low threshold. The logging case is covered in logging from asyncio tasks without blocking.

Reading lag alongside everything else

The metric is most useful in combination, and three pairings account for most of its diagnostic value.

Lag against request latency. The primary reading, and the one the metric exists for. Both rising together means the process is the constraint; latency rising while lag stays flat means the time is being spent waiting on something outside the process. That single distinction is what the first ten minutes of a latency incident is usually spent establishing by other means.

Lag against GC pause duration. When lag rises in spikes rather than as a level, garbage collection is the first suspect, because a generation-2 collection blocks the thread that triggered it. If the spike cadence matches the collection cadence, the investigation moves to memory and allocation rather than to a search for a blocking call.

Lag against CPU utilisation. Lag with the CPU saturated means the process has more work than it can do, and the answer is capacity or efficiency. Lag with the CPU idle means something is blocking on I/O without yielding, which is a bug rather than a capacity problem — and the two remedies are entirely different, which is why the pairing matters.

Lag Other signal Reading
Rising with latency — the process is the constraint
Flat while latency rises — the time is outside the process
Spiking GC pauses matching allocation, not blocking
Rising CPU saturated capacity or efficiency
Rising CPU idle a blocking call: a bug

Threaded services and the equivalent metric

The same question — is the process keeping up with its own scheduled work — applies to a threaded service, and the measurement is different because there is no single loop to be late.

The closest equivalent is executor queue depth: the number of work items waiting for a thread. A pool at its ceiling with a growing queue is the threaded analogue of loop lag, and it has the same property of being invisible in per-request timings, because the waiting happens before the request's own work begins.

from prometheus_client import Gauge

EXECUTOR_QUEUE = Gauge("python_executor_queue_depth", "Work items waiting for a thread", ["pool"])

def observe_pool(pool: ThreadPoolExecutor, name: str) -> None:
    EXECUTOR_QUEUE.labels(name).set(pool._work_queue.qsize())

The private attribute is unfortunate and is the only way to get the number without wrapping every submission; wrapping is the cleaner alternative if you control every call site.

Running it in every environment

One deployment detail is worth getting right: the sampler needs to run in whichever process serves traffic. Under a prefork or multi-worker server, that means starting it per worker rather than once at import — the same rule that applies to the tracing provider, and for the same reason. A monitor started in the parent measures the parent's loop, which serves nothing and is always idle, producing a metric that reports perfect health regardless of what the workers are doing.

That failure is quiet and convincing, because the metric exists, updates, and shows exactly what you hoped to see. Verifying that the sample count rises proportionally to the worker count is the check that catches it.

Frequently Asked Questions

What exactly does event loop lag measure?

How late the loop is running work it already agreed to run. If a coroutine asks to sleep for one second and resumes 1.08 seconds later, the loop was busy with something else for 80 milliseconds past the due time. Since the loop is single-threaded, that delay applies to every other ready callback too — so one sampler measures a property of the whole loop, not of itself.

What causes lag?

Anything that occupies the loop thread without yielding: a synchronous file or network write, a CPU-bound loop, a large JSON parse, an import performed at request time, a synchronous log handler, or a database driver used in blocking mode. Garbage collection contributes as well, since a collection blocks the thread that triggered it. What they share is that none of them are visible as slow requests in the code that caused them — they are visible as slow requests everywhere else.

What lag value is acceptable?

Depends on your latency budget, but as a starting point: a p99 under 10 milliseconds is comfortable, 10 to 50 milliseconds is worth investigating, and consistently above 100 milliseconds means the loop is a bottleneck regardless of what any dependency is doing. The important thing is not the absolute number but whether it moves when latency moves.

Does the sampler itself add lag?

Negligibly. One coroutine waking a few times a second, doing two clock reads and one histogram observation, is a few microseconds of work per sample. If sampling every 100 milliseconds, that is still far below the resolution of anything you are trying to detect.

How do I find which coroutine is blocking?

asyncio's debug mode with a lowered slow_callback_duration logs a warning naming the callback whenever one exceeds the threshold. Run it in staging under load rather than in production — debug mode adds its own overhead — and the warning usually names the coroutine directly. When it names something generic, a sampling profiler that captures the loop thread's stack when lag exceeds a threshold is the next step.

Related Guides