Skip to content

Observability & Tracing for Asyncio Services

The standard three signals — metrics, traces, logs — apply to an async service exactly as they do to any other, and then asyncio adds failure modes none of them see by default. A synchronous call in a handler makes every concurrent request slow, and the latency histogram shows only that everything got worse together. A task leak grows until the process is killed, with no metric moving. A queue behind a semaphore fills while the loop looks idle. Each of these has a one-line measurement — event loop lag, live task count, queue wait — and a service without them is diagnosed by guessing.

The cost of all this is smaller than most teams assume: a labelled counter increment measured at 0.84 µs, a sampled span at 3.91 µs, a structured JSON log line at 4.04 µs. What is expensive is doing it carelessly — 5,000 distinct label values turned a 1.5 KiB metrics scrape into 774 KiB, and 50 log lines to a slow sink produced 103 ms of event loop lag. This section covers each signal with its measurements and its specific trap. The parent section, Resilience, Cancellation & Error Handling, covers what to do once you can see the problem.

Scope of this section:

  • The asyncio-specific metrics: loop lag, task count, queue wait against service time.
  • Tracing with OpenTelemetry, and how span context follows contextvars through tasks.
  • Structured logging that survives interleaved requests and never blocks the loop.
  • Joining the three signals with trace and request identifiers.
  • Cardinality, sampling and volume: keeping observability from becoming the incident.

Architectural principles

  • Measure the loop, not just the requests. Event loop lag distinguishes "our dependency is slow" (lag flat, latency high) from "we are blocking the loop" (lag rises with load). No request-level metric can tell those apart.
  • Split waiting from working. Queue wait and service time are different numbers with opposite remedies. Measured across increasing load, service time stayed at 5.3 ms while wait went from 0 ms to 471 ms — the total-latency chart showed only "slower".
  • Cardinality is the budget. Metric labels must be things you group by, with bounded values. Identifiers belong on spans and in logs, which are built for them.
  • Observability must not block. Logging is synchronous I/O, span export can be, and a metrics scrape serialises on the loop. Each needs a deliberate handoff — a queue, a batch processor, a bounded registry.
  • Signals must join. A trace id in every log line and an exemplar on every histogram turn three separate systems into one investigation.
Three signals, three questions 4 stacked layers from metrics to loop signals. Three signals, three questions metrics is the service healthy? 0.84 µs per counter, bounded labels traces why was THIS request slow? 3.91 µs per sampled span logs what exactly happened? 4.04 µs per structured line loop signals lag, task count, queue wait the ones only async services have All three are cheap to record; the expensive parts are cardinality, sampling and slow sinks.

Execution model: one thread, one context, many requests

Everything specific to observing an async service follows from the fact that thousands of logical requests share one thread. A thread-local is useless; contextvars is the mechanism that works, and both OpenTelemetry's current span and structlog's bound context use it. The consequences are consistent across both: an awaited call sees the caller's context, a task created inside it gets a copy, and a task created after the enclosing scope has ended gets nothing — verified for spans, where a task created after its span ended had no parent and started a new trace.

That single rule explains the two most common observability bugs in async services. Background work started from a request appears as an orphan trace or logs without a request id, because the context it would have inherited was gone by the time it was spawned. The fix is to capture what you need at spawn time — a trace.Link, or the bound log context — rather than relying on inheritance that has already lapsed.

The second consequence is about cost. Because there is one thread, anything synchronous that observability does lands on the critical path of every concurrent request. A SimpleSpanProcessor exporting over the network, a log handler writing to a slow file, a /metrics endpoint serialising a huge registry: each is a small cost per event multiplied by an event rate you did not design for, on a thread that cannot do anything else meanwhile.

How the three signals join up 5 stages from a metric alerts to read the fields. How the three signals join up a metric alerts p99 or queue wait find a trace same window, sampled take the trace id from the slow span filter the logs by that trace id read the fields tenant, target, duration The join only works if every log line carries the trace id, which costs one binding per request.

Pattern catalogue

Sample the loop's own health

async def sample_loop_health(interval: float = 0.05) -> None:
    while True:
        started = time.perf_counter()
        await asyncio.sleep(interval)
        LOOP_LAG.set(max(0.0, time.perf_counter() - started - interval))
        TASKS.set(len(asyncio.all_tasks()))

A handler blocking for 0.6 s produced 587 ms of lag in testing; a 500-request burst produced 128 ms. See exporting Prometheus metrics from asyncio.

Split queue wait from service time

job = await queue.get()
started = time.perf_counter()
QUEUE_WAIT.observe(started - job.enqueued_at)
await handle(job)
SERVICE_TIME.observe(time.perf_counter() - started)

Rising wait with flat service means saturation; rising service means the work got slower. See measuring queue wait and service time separately.

Trace boundaries, sample by parent

provider = TracerProvider(sampler=ParentBased(TraceIdRatioBased(0.1)))
provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter()))

ParentBased keeps sampled traces whole; BatchSpanProcessor keeps export off the loop. See tracing asyncio services with OpenTelemetry.

Bind log context once per request

structlog.contextvars.bind_contextvars(request_id=request_id, tenant=tenant,
                                       trace_id=format(span_context.trace_id, "032x"))
try:
    ...
finally:
    structlog.contextvars.clear_contextvars()

Three concurrent requests produced three cleanly separated field sets, with no leakage. See structured logging for async services.

Keep slow sinks off the loop

listener = logging.handlers.QueueListener(log_queue, *real_handlers)
listener.start()
logging.getLogger().handlers = [logging.handlers.QueueHandler(log_queue)]

The same 50 lines that caused 103 ms of lag caused 1 ms through the queue.

Record outcomes with durations, not progress

log.info("upstream_call", target="billing", duration_ms=round(elapsed * 1000, 1),
         status=response.status_code, attempt=attempt)

One line per external call, with a measured duration and an outcome, answers "which dependency was slow" from logs alone. A line at the start and another at the end doubles the volume and answers nothing a duration field does not — and in an async service, where lines from many requests interleave, the "started" line is separated from its "finished" line by hundreds of unrelated entries anyway.

Report health from the same numbers

ok = state.ready and state.loop_lag < LAG_BUDGET
return JSONResponse({"ready": ok, "loop_lag_ms": round(state.loop_lag * 1000)},
                    status_code=200 if ok else 503)

The lag gauge that feeds the metrics system is also the right input to a readiness probe: an instance whose loop cannot keep up should stop receiving traffic until it can, as covered in health and readiness probes. Measuring once and using the value in both places keeps the probe and the dashboard from disagreeing during an incident.

Which signal answers which question A grid of 5 rows by 2 columns. Which signal answers which question question signal look at are we slow? metrics latency histogram, per route are we saturated? metrics queue wait, not depth is something blocking the loop? metrics event loop lag why was this request slow? traces the span tree for that trace id what did this request do? logs lines filtered by request id A question with no signal behind it becomes a guess during an incident.

Resource boundaries

Resource What consumes it How to size and bound it
Event loop time Every recorded metric, span and log line Sub-microsecond each; the sink is what costs
Metric series Distinct label combinations Bounded label values only; audit the scrape size
Span volume Spans per request times request rate Sample with ParentBased; instrument boundaries
Export queues Spans and log records awaiting export Bounded queues; alert on drops
Log volume Lines per request times rate One line per unit of work; sample routine paths
Scrape cost Registry size at scrape time Keep cardinality low; 1.5 KiB scraped in 2.0 ms
Storage and bill All of the above, retained Retention per signal; traces sampled, logs sampled, metrics aggregated

The metric-series row is the one that becomes a budget conversation: one careless label turned a 1.5 KiB scrape into 774 KiB in a single process, and the backend multiplies that by every instance. The export-queue row is the one that fails quietly: a span exporter whose queue fills drops spans without raising anything, so a service can look fully instrumented while sending a fraction of its traces. Both belong on a dashboard of their own — the observability system needs observing, and the cheapest version of that is a scrape-size panel and a dropped-spans counter next to the signals they protect.

Integrated production example

A service with all three signals wired together: Prometheus metrics including loop lag and the queue-wait split, OpenTelemetry tracing with parent-based sampling, structured logs carrying the trace id through a non-blocking handler, and load shedding when the queue is full.

REQS = Counter("requests_total", "", ["route", "status"], registry=REG)
QWAIT = Histogram("queue_wait_seconds", "", registry=REG,
                  buckets=(0.001, 0.005, 0.05, 0.25, 1.0, 5.0))
SVC = Histogram("service_seconds", "", registry=REG, buckets=(0.001, 0.005, 0.05, 0.25, 1.0))
LAG = Gauge("event_loop_lag_seconds", "", registry=REG)
TASKS = Gauge("asyncio_tasks", "", registry=REG)
QDEPTH = Gauge("queue_depth", "", registry=REG)

jobs: asyncio.Queue = asyncio.Queue(maxsize=500)            # bounded: shedding is possible


async def sampler() -> None:
    while True:
        started = time.perf_counter()
        await asyncio.sleep(0.05)
        LAG.set(max(0.0, time.perf_counter() - started - 0.05))
        TASKS.set(len(asyncio.all_tasks()))
        QDEPTH.set(jobs.qsize())


async def worker() -> None:
    while True:
        enqueued_at, payload = await jobs.get()
        started = time.perf_counter()
        QWAIT.observe(started - enqueued_at)                # waiting
        with tracer.start_as_current_span("job") as span:
            span.set_attribute("job.kind", payload["kind"])
            await handle(payload)
        SVC.observe(time.perf_counter() - started)          # working
        jobs.task_done()


async def submit(request):
    started = time.perf_counter()
    structlog.contextvars.bind_contextvars(
        request_id=request.headers.get("x-request-id", uuid4().hex), route="/submit")
    try:
        with tracer.start_as_current_span("submit") as span:
            ctx = span.get_span_context()
            structlog.contextvars.bind_contextvars(
                trace_id=format(ctx.trace_id, "032x"))       # joins logs to traces
            try:
                jobs.put_nowait((time.perf_counter(), {"kind": "email"}))
            except asyncio.QueueFull:
                REQS.labels(route="/submit", status="503").inc()
                log.warning("shed", reason="queue_full")     # counted AND logged
                return JSONResponse({"error": "busy"}, status_code=503)
            log.info("accepted")
            REQS.labels(route="/submit", status="202").inc()
            return JSONResponse({"accepted": True}, status_code=202)
    finally:
        LAT.labels(route="/submit").observe(time.perf_counter() - started)
        structlog.contextvars.clear_contextvars()            # never leak into the next request

Driven with 3,000 submissions at a client concurrency of 100, against four workers doing 5 ms of work each: 2,201 accepted and 799 shed when the bounded queue filled, queue_wait_seconds_sum of 1,310 s against service_seconds_sum of 31 s — that is, 97% of the total time was waiting, which is what saturation looks like in numbers. Event loop lag stayed at 0.6 ms throughout, correctly reporting that nothing was blocking the loop, and 541 spans were exported for 10% sampling. Every accepted request produced one structured line carrying its trace_id.

Diagnostic Hook — the three numbers, in order

When something is wrong, read them in this sequence. Event loop lag first: if it is high, something synchronous is on the loop, and no amount of scaling will help until it is found — look for CPU work, a blocking driver, or a slow log sink. Queue wait against service time second: wait rising with flat service means saturation, which is a capacity or shedding decision; service rising means the work itself got slower and the answer is downstream. Task count third: a number that never returns to baseline is a leak, and it is the only warning you get before the process is killed. Only then open a trace, because by that point you know which question you are asking. Alert on lag above 100 ms, on queue wait above your shedding threshold, and on task count growth over an hour.

Something is wrong: which number first? A decision on What does the loop say with 3 outcomes. Something is wrong: which number first? What does the loop say? lag is high something blocks the loop CPU work or a sync call lag flat, queue wait high saturation add capacity or shed both flat, latency high a dependency follow the trace downstream Three numbers, in order, answer most incidents before anyone opens a trace.

Failure modes

Failure mode Root cause Detection Fix
Everything slow at once A blocking call on the loop Loop lag tracks the call duration Offload to a thread or process
Latency rises, dependencies fine Saturation of a bounded resource Queue wait rises, service flat Add capacity, or shed
Memory grows until the pod dies Task or connection leak asyncio_tasks climbing monotonically Track and bound spawned tasks
Metrics backend rejects writes Unbounded label cardinality Scrape size growing with traffic Route templates, not paths
Logging causes the outage Slow sink on the loop; per-error logging Lag correlates with log volume QueueHandler; rate-limit repeats
Traces have holes Head sampling without ParentBased Spans with missing parents ParentBased sampler everywhere
Background work is untraceable Task created after the span ended Orphan traces, logs without a request id Capture a link at spawn time
Alerts fire but explain nothing Signals not joined No trace id in logs Bind trace and request ids once per request

Frequently Asked Questions

What should I monitor in an asyncio service that I would not in a synchronous one?

Event loop lag, live task count, and queue wait separated from service time. Lag catches blocking work that makes every concurrent request slow, task count catches leaks before they kill the process, and the wait/service split distinguishes saturation from a slow dependency.

How much does observability cost an async service?

Per event, almost nothing: 0.84 µs for a labelled counter, 3.91 µs for a sampled span, 4.04 µs for a structured log line. The costs that matter are cardinality — 5,000 label values took one scrape from 1.5 KiB to 774 KiB — and slow sinks, where 50 log lines caused 103 ms of loop lag.

Why do my background tasks have no trace or request context?

Because they were created after the enclosing span or log context ended, and contextvars are copied at task creation. Capture what you need at spawn time — a trace.Link, or the bound fields — instead of relying on inheritance that has already lapsed.

Should I alert on latency, queue depth, or queue wait?

Queue wait. Latency mixes waiting with working, and depth has no fixed meaning — 1,000 items is trivial at 10,000 per second and an outage at 10. Wait is zero in a healthy system at any traffic level and directly interpretable when it is not.

How do I connect a slow trace to its logs?

Bind the trace id into the log context at the start of each request, formatted as hex, so every line carries it. Then a slow span leads to that request's log lines in one query. Going the other way, metric exemplars carry a trace id from a histogram bucket to a representative trace.