Skip to content

Measuring Event Loop Lag in Production

Every async service eventually hits the same wall: request latency degrades, and no per-dependency metric explains it. The database is fast, the upstream is fast, CPU is moderate, and yet responses take hundreds of milliseconds longer than the sum of their parts. That gap is queueing on the event loop — the time a callback spent waiting for its turn rather than doing work — and it is invisible unless you measure it directly. Event loop lag is that measurement: the difference between when a callback was scheduled to run and when it actually ran.

It is the most valuable single number an async service can export, because it is causally upstream of everything else. Lag rises before error rates do, it rises for reasons your dependency dashboards cannot show, and it distinguishes "our downstream is slow" from "we cannot get to the work". This guide builds the probe, keeps its overhead honest, exports it as a histogram, sets thresholds from your latency budget, and shows how to read the p50/p99 shape to tell one long callback from genuine saturation.

Prerequisites

  • Python 3.11+, standard library only for the probe itself.
  • A metrics client for the export step (prometheus_client, OpenTelemetry, or statsd). The examples use a small stub you can swap for either:
pip install prometheus-client
Where the lag number comes from Three lanes illustrating the definition of loop lag as the overshoot past a timer deadline. Where the lag number comes from scheduled sleep(0.25) starts timer due loop still running other callbacks observed probe resumes one probe cycle lag = actual resume time − (start + interval): the queue ahead of the timer.

1. Write the probe

The probe is a coroutine that sleeps for a known interval and measures the overshoot. loop.time() is the loop's own monotonic clock, so the measurement is unaffected by wall-clock adjustments.

import asyncio


async def lag_probe(interval: float = 0.25) -> None:
    """Sample the loop's queueing delay forever. One timer per interval."""
    loop = asyncio.get_running_loop()
    while True:
        start = loop.time()
        await asyncio.sleep(interval)
        lag = loop.time() - start - interval
        record(max(lag, 0.0))          # negative values are clock noise; clamp

The physics are worth internalising: asyncio.sleep(interval) schedules a timer for now + interval. When the timer expires, the callback is appended to the ready queue and runs only after everything already queued ahead of it. The overshoot is therefore the total time the loop spent doing other things past the deadline — exactly the delay any real callback would have suffered at that instant. Verify: on an idle service the value hovers around 0.2–1.5 ms (timer resolution plus scheduling). If your baseline is higher than that, you are already queueing at rest.

2. Pick an interval that samples without dominating

The interval is a trade-off between resolution and cost. Every wakeup is one timer expiry plus one callback — cheap, but not free — and a probe that fires too often starts to contribute to the very queue it measures.

# Practical starting points
FAST = 0.05     # 20 samples/s: incident debugging, short windows only
NORM = 0.25     #  4 samples/s: the production default
SLOW = 1.00     #  1 sample/s: very high task counts or tiny containers

At 250 ms you take 240 samples a minute, which is plenty to build a stable percentile distribution, and the probe's own cost is far below the noise floor of any real workload. Shorter intervals do not detect more stalls — a 500 ms stall is caught by any interval — they only pin down its start time more precisely. Verify: run the probe alone in an otherwise idle process at your chosen interval and confirm p99 stays under ~2 ms; if the probe alone shows lag, the interval is too aggressive for that host.

3. Export it as a histogram, not a gauge

A gauge overwrites the previous value and hides exactly the events you care about: brief stalls between scrapes. A histogram keeps the distribution, so percentiles survive aggregation across instances.

import asyncio
from prometheus_client import Histogram

LOOP_LAG = Histogram(
    "event_loop_lag_seconds",
    "Delay between a callback's scheduled time and its execution",
    buckets=(0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0),
)


async def lag_probe(interval: float = 0.25) -> None:
    loop = asyncio.get_running_loop()
    while True:
        start = loop.time()
        await asyncio.sleep(interval)
        LOOP_LAG.observe(max(loop.time() - start - interval, 0.0))

The buckets matter as much as the metric. Start at 1 ms (below it, everything is healthy and indistinguishable) and extend to 5 s (above it, the process is effectively down); the interesting resolution is 10–250 ms, so weight the buckets there. Verify: scrape the endpoint and confirm event_loop_lag_seconds_bucket is populated across several buckets under load — if every sample lands in the first bucket, your service is healthy and you can tighten the low end.

Histogram buckets and what each range means Five severity bands of loop lag with an escalating interpretation for each. Histogram buckets and what each range means < 1 ms — timer floor healthy 1–10 ms — normal load watch p99 10–100 ms — queueing SLO at risk 100 ms–1 s — stalling page > 1 s — effectively down incident Bar length encodes severity, not frequency — the distribution is your traffic, this is the reading. Weight the buckets where decisions change, between 10 ms and 250 ms.

4. Set alert thresholds from your latency budget

Lag is a leading indicator, so thresholds should come from the SLO it will damage, not from a round number. The rule of thumb: alert when p99 lag exceeds roughly a tenth of your request latency budget, because at that point loop queueing is a material fraction of every request's time.

# Prometheus alerting rules
- alert: EventLoopLagHigh
  expr: histogram_quantile(0.99, sum by (le, instance) (rate(event_loop_lag_seconds_bucket[5m]))) > 0.02
  for: 5m
  labels: {severity: warning}
  annotations:
    summary: "p99 event loop lag above 20 ms on {{ $labels.instance }}"

- alert: EventLoopStalled
  expr: histogram_quantile(0.99, sum by (le, instance) (rate(event_loop_lag_seconds_bucket[1m]))) > 0.5
  for: 1m
  labels: {severity: critical}
  annotations:
    summary: "event loop stalling: p99 lag above 500 ms"

Two tiers work better than one. The warning tier (a tenth of the budget, over five minutes) catches creeping degradation — a growing payload, a slowly filling cache — while the critical tier (half a second, over one minute) catches an outright stall such as a blocking call newly introduced by a deploy. Verify: replay a known blocking call in staging (time.sleep(0.4) inside a handler) and confirm both alerts fire in the expected order.

5. Read the shape: p50 versus p99

The two percentiles answer different questions, and the pair identifies the failure class before you open a profiler.

p50  1 ms   p99  400 ms   → one rare long callback (blocking call, GC pause)
p50 40 ms   p99  60 ms    → sustained overload: the queue never empties
p50  1 ms   p99    2 ms   → healthy; latency problems are downstream
p50 15 ms   p99  900 ms   → both: an overloaded loop plus an occasional stall

A high p99 with a low p50 is episodic: most of the time the loop is idle enough to run the probe on schedule, and occasionally something monopolises it. That is a blocking call or a garbage-collection pause, and the fix is attribution — enable debug mode with a low slow_callback_duration. A p50 that has lifted off the floor is structural: there is simply more work arriving than the loop can drain, and no single callback is at fault. That needs capacity or admission control — more instances, a smaller concurrency limit, or queue backpressure at the ingress. Verify: annotate a dashboard panel with both percentiles on the same axis; the two lines diverging is the signature of the episodic case, moving together is the structural one.

6. Correlate with task population

Lag alone cannot distinguish "each callback got slower" from "there are simply more callbacks". Sampling the live task count next to it closes that gap for a few microseconds every ten seconds.

import asyncio
from prometheus_client import Gauge

TASKS = Gauge("event_loop_tasks", "Tasks not yet done on this loop")


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

Keep this one slow. all_tasks() builds a new set of every live task, so at 50k tasks it is milliseconds of work — negligible every ten seconds, damaging every 100 ms. Verify: under a load test, task count should rise with concurrency and return to baseline afterwards; a count that never returns is a task leak, which the task inventory dump will name for you.

Lag and task count read together A three-by-two matrix pairing lag percentile shapes with task-count trends. Lag and task count read together task count flat task count rising p50 low, p99 low healthy — look downstream work arriving faster p50 low, p99 high one long callback leak plus a stall p50 raised sustained overload saturation — shed load Two cheap gauges classify the incident before any profiler is opened.

Verification

  • Baseline is quiet. With production traffic at normal levels, p99 lag sits in single-digit milliseconds and p50 near the timer floor.
  • The probe is not the load. Removing the probe does not measurably change service latency; adding it does not change p99 by more than its own interval jitter.
  • Alerts fire on injected stalls. A deliberate time.sleep() in staging trips the warning and critical alerts at the expected thresholds, and the dashboard shows the p50/p99 divergence described above.

Pitfalls and edge cases

  • Using time.time() instead of loop.time(). Wall-clock jumps (NTP steps, container suspend) produce nonsense samples, including large negatives. Always measure with the loop's monotonic clock.
  • Exporting a gauge. A gauge scraped every 15 s misses a 300 ms stall entirely unless it happens to land on the scrape. Histograms preserve the tail.
  • One probe per process, not per loop. A service running a second event loop in a worker thread needs its own probe inside that thread; asyncio.sleep() in the main loop says nothing about the other one.
  • Probes in the same TaskGroup as the workload. Good practice — if the probe dies you lose observability silently otherwise — but remember that a crashing probe will then cancel its siblings, so keep the probe body trivially safe.
  • Confusing lag with utilisation. A loop can show near-zero lag at 90% CPU (many short callbacks) or 400 ms lag at 20% CPU (one blocking call). Lag measures delay, not busyness; alert on lag, capacity-plan on both.
  • uvloop changes the floor, not the meaning. Under uvloop the timer floor drops and callbacks dispatch faster, so re-baseline your thresholds after switching — the same absolute lag is a worse signal on a faster loop.

Frequently Asked Questions

What is a normal event loop lag value?

On an idle or lightly loaded service, p50 lag sits around 0.2-1.5 ms — timer resolution plus one scheduling hop — and p99 stays under a few milliseconds. Anything sustained above about 20 ms means loop queueing is already a material part of request latency for a typical web service, and a p99 above 500 ms means the loop is effectively stalling.

How often should the lag probe sample?

Every 250 ms is a good production default: 240 samples a minute is enough for stable percentiles, and the cost is one timer plus one callback per sample. Use 50 ms only during a live incident window, and 1 s on very small containers or processes with tens of thousands of tasks.

Should event loop lag be a gauge or a histogram?

A histogram. A gauge only holds the most recent sample, so a brief stall between scrapes disappears, and per-instance gauges cannot be aggregated into a meaningful fleet percentile. A histogram with buckets from 1 ms to 5 s preserves the tail and aggregates correctly across instances.

Does a lag probe itself slow down the event loop?

Not meaningfully at sane intervals. One wakeup every 250 ms is a single timer expiry plus a few microseconds of callback work, orders of magnitude below the noise of any real workload. The probes that do cost something are the ones that walk all tasks; keep those at ten seconds or slower.