Finding Latency Bottlenecks with Critical Path Analysis

Problem Framing

A request that should take 120 ms is taking 900 ms in production, and the distributed trace shows two dozen spans stacked into a waterfall. The instinct is to find the widest bar and start optimising it. That instinct is frequently wrong. The widest bar is often a parent span whose duration is nothing more than the sum of its children, or a branch that runs in parallel with — and is masked by — the branch that is actually gating the response. Teams routinely spend a sprint tuning a database call that turns out to have three hundred milliseconds of slack, while the real culprit is a serial chain of small spans nobody looked at twice.

Critical path analysis is the discipline that fixes this. The critical path is the specific chain of spans that determines total request latency: the sequence where shortening any one span shortens the whole request, and lengthening any one span lengthens it. Everything off the critical path has slack. This page shows how to compute self-time, walk the span tree to find that path, distinguish serial waits from parallel fan-out, and confirm your conclusion in the Jaeger or Tempo UI before you touch a line of code.

Prerequisites

Before working through this page, you should have:

  • A trace backend with waterfall rendering — Jaeger 1.50+ or Grafana Tempo 2.3+ — and at least one slow trace already captured for a real endpoint.
  • OpenTelemetry instrumentation emitting spans with accurate startTimeUnixNano and endTimeUnixNano fields. If your services are only partially instrumented, read auto vs manual instrumentation first — missing spans skew the critical path.
  • NTP synchronised across all hosts. Critical path math relies on comparing timestamps recorded by different machines; unsynchronised clocks make cross-service gaps meaningless.
  • Familiarity with the span lifecycle and parent-child relationships, since the critical path is computed by walking the parent-child graph.
  • The ability to export a single trace as JSON (both backends expose an HTTP API for this) so you can compute self-time programmatically rather than eyeballing bars.

Concept Deep-Dive: Reading a Waterfall Without Being Fooled by It

A trace waterfall is a Gantt chart of spans laid out on a shared time axis. Its power is also its trap: the eye is drawn to horizontal length, but length alone answers the wrong question. Four concepts separate a correct reading from a misleading one.

Wall-time is a span’s total duration — end − start. It is what the bar’s width shows. Self-time (sometimes called exclusive time) is wall-time minus the time covered by the span’s children. A span that opens, fires two database queries sequentially, and returns has almost no self-time of its own; its width is inherited from the queries. Self-time is where the actual CPU or I/O cost lives, and it is the number worth optimising.

Serial versus parallel describes how sibling spans relate on the time axis. Serial siblings run back-to-back: child B starts after child A ends, so their durations add. Parallel (fan-out) siblings overlap: they start close together and run concurrently, so the parent only waits for the slowest of them, not their sum. This single distinction is why the longest span is so often not the bottleneck — a 400 ms span running in parallel with a 420 ms sibling contributes zero marginal latency, because the 420 ms sibling was going to gate completion anyway.

Span-count versus span-duration is the last axis. One 300 ms span and a hundred sequential 3 ms spans both total 300 ms of latency, but they are different bugs with different fixes. The single span is a slow operation to be tuned or cached; the hundred small spans are an N+1 pattern to be batched. The waterfall renders them very differently — one fat bar versus a dense picket fence — and the fix follows from which shape you see.

The critical path threads through all of this. Formally, it is the longest-duration path from the root span’s start to the root span’s end, where “path” follows parent-to-child edges and, within a set of parallel children, always takes the child that finishes last. Reducing a span’s duration only helps the request if that span lies on this path.

Span waterfall with critical path highlighted A request root span spans the full width. Beneath it, an auth check runs first, then a fan-out of three parallel calls — cache, inventory, and pricing — where pricing finishes last, then a serial render step. The critical path follows root, auth, pricing, and render, drawn in amber, while the shorter cache and inventory branches are drawn plain to show they have slack. 0 ms 450 ms 900 ms GET /checkout (root · 900 ms wall · 20 ms self) auth.verify · 180 ms ↓ fan-out (parallel) cache · 130 ms inventory.lookup · 230 ms pricing.compute · 460 ms (gates the fan-out) render.page · 240 ms on critical path — shortening it shortens the request off critical path — has slack; inventory can grow ~230 ms before it matters Critical path = auth (180) + pricing (460) + render (240) + root self (20) = 900 ms inventory is the second-longest span but contributes zero marginal latency — it hides behind pricing.
The critical path runs through auth, pricing, and render. Inventory is the second-widest bar yet sits entirely off the path — optimising it would not move the response time at all.

The diagram makes the trap concrete. inventory.lookup at 230 ms is the second-longest span in the trace, and a length-first reading would target it. But it runs in parallel with pricing.compute at 460 ms, which finishes 230 ms later. The fan-out cannot complete until pricing returns, so inventory has roughly 230 ms of slack — you could double its duration and the request would not slow down by a millisecond. The critical path is auth → pricing → render plus the root’s own self-time, and those are the only spans worth touching.

Step-by-Step Implementation

Step 1: Export the Trace as Structured Span Data

Eyeballing bars is fine for a first pass, but self-time and the critical path are arithmetic, so pull the raw spans. Both backends expose the full trace over HTTP.

# Jaeger: fetch a trace by ID as JSON
curl -s "http://jaeger:16686/api/traces/${TRACE_ID}" \
  | jq '.data[0].spans[] | {id: .spanID, ref: (.references[0].spanID // null), name: .operationName, start: .startTime, dur: .duration}'

# Tempo: fetch a trace by ID (OTLP-shaped JSON)
curl -s "http://tempo:3200/api/traces/${TRACE_ID}" \
  | jq '.batches[].scopeSpans[].spans[] | {id: .spanId, ref: .parentSpanId, name: .name, start: .startTimeUnixNano, dur: (.endTimeUnixNano - .startTimeUnixNano)}'

Jaeger reports startTime and duration in microseconds; Tempo reports nanosecond epoch timestamps. Normalise to a single unit before you do any math — mixing microseconds and nanoseconds silently produces a critical path off by three orders of magnitude.

Step 2: Compute Self-Time for Every Span

Self-time is wall-time minus the union of child intervals. Using the union (not the naive sum of child durations) matters, because overlapping parallel children would otherwise over-subtract and produce a negative self-time.

from dataclasses import dataclass, field

@dataclass
class Span:
    id: str
    parent: str | None
    name: str
    start: int          # normalised to microseconds
    dur: int            # microseconds
    children: list = field(default_factory=list)

def self_time(span: Span) -> int:
    # Merge child intervals so overlapping (parallel) children
    # are counted once, not twice.
    intervals = sorted((c.start, c.start + c.dur) for c in span.children)
    covered, cursor = 0, None
    for begin, end in intervals:
        if cursor is None or begin > cursor:
            covered += end - begin          # fresh interval
            cursor = end
        elif end > cursor:
            covered += end - cursor         # extend the current merged block
            cursor = end
    # Self-time is wall-time minus the wall-clock window children occupied.
    return span.dur - covered

A span whose self-time is a large fraction of its wall-time is doing real work locally. A span whose self-time is near zero is an aggregator — its cost lives in a descendant, so keep walking down.

Step 3: Walk the Tree to Identify the Critical Path

Start at the root and, at each node, follow the child that ends last. That child gates its parent’s completion, so it is on the critical path. Repeat until you reach a leaf. Accumulate each node’s self-time as the latency that node contributes.

def critical_path(root: Span) -> list[tuple[str, int]]:
    """Return [(span_name, self_time_contribution), ...] along the critical path."""
    path, node = [], root
    while node is not None:
        path.append((node.name, self_time(node)))
        if not node.children:
            break
        # The child that finishes LAST determines when this span can end.
        # (Ties broken by later start, then longer duration.)
        node = max(node.children, key=lambda c: (c.start + c.dur, c.start, c.dur))
    return path

# The sum of the self-time column equals the root wall-time (minus clock-skew noise).
# Sort that column descending to rank the true bottlenecks.

The output is a ranked list of where the request’s time actually went. In the waterfall example above it reads pricing.compute 460ms, render.page 240ms, auth.verify 180ms, root 20ms — and crucially, inventory.lookup never appears, because it was never on the path.

Step 4: Classify the Bottleneck on That Path

Knowing which span is on the critical path is half the answer; the fix depends on why it is slow. Three signatures cover most cases:

def classify(span: Span) -> str:
    kids = span.children
    same_name = [c for c in kids if c.name == (kids[0].name if kids else "")]

    # N+1: many short, same-named children run back-to-back (serial).
    serial = all(
        kids[i].start >= kids[i-1].start + kids[i-1].dur - 1000  # ~1ms tolerance
        for i in range(1, len(kids))
    ) if len(kids) > 1 else False
    if len(same_name) >= 5 and serial:
        return "N+1 — batch these into a single query/request"

    # Serial wait: high self-time on a leaf that is pure I/O.
    if not kids and self_time(span) > 100_000:      # >100 ms
        return "slow leaf — cache, index, or tune the downstream call"

    # Lock contention: high self-time but the span issues no downstream work,
    # and duration varies wildly run-to-run (check p50 vs p99 for the operation).
    if not kids and self_time(span) == span.dur:
        return "possible lock/pool wait — compare p50 vs p99 for this op name"

    return "aggregator — descend into the slowest child"

An N+1 shows as a picket fence of identical serial children. A genuine serial wait is a single fat leaf with high self-time — a slow query, an un-cached upstream call, a cold-start. Lock or connection-pool contention hides as a leaf whose self-time is its entire duration and whose p99 is far above its p50 for the same operation name; the span is “running” but really blocked waiting for a resource.

Step 5: Confirm in the Jaeger or Tempo UI

Arithmetic finds the path; the UI confirms it and gives you the attributes to act on. In Jaeger, open the trace, click the critical-path span, and read its tags — db.statement, http.url, peer.service tell you exactly what it was doing. In Tempo via Grafana, use TraceQL to pull every instance of the suspect operation and confirm the pattern holds beyond the one trace:

{ name = "pricing.compute" && duration > 300ms }

If that query returns a steady stream across many traces, the bottleneck is systemic, not a one-off outlier — which is what justifies the optimisation work.

Verification

You have correctly identified the bottleneck when three things hold:

  1. The self-time column sums to the root wall-time, within a small tolerance for clock skew. If it does not, a span is missing from your export or a parent-child reference is broken — fix the data before trusting the path.
  2. A TraceQL or Jaeger query for the suspect span across many traces shows the same span dominating the critical path, not just in your single sample. One slow trace can be an outlier; a hundred is a pattern.
  3. A back-of-envelope prediction matches reality after the fix. If the critical path says pricing.compute contributes 460 ms and you cache it down to 40 ms, the p50 for /checkout should drop by roughly 420 ms. If it drops by far less, you were off the true critical path and slack elsewhere absorbed your win.

A quick sanity query in Tempo to rank operations by contribution across a window:

{ } | select(name, duration) | by(name)

Compare the aggregated durations against your per-trace critical path; the operations at the top of both lists should agree.

Edge Cases and Gotchas

  1. Async gaps that no span covers. When a producer enqueues a message and a consumer picks it up later, the queue wait is real latency that lives between two spans, not inside either. The critical path walk sees a gap with no child to descend into. Instrument the enqueue-to-dequeue interval explicitly, or read handling async boundaries to make the hand-off visible as a span.

  2. Missing spans skew the path. If a service is uninstrumented, its work shows up as unexplained self-time on the calling span, or as a gap. The critical path will point at the wrong place — the last instrumented ancestor — because it cannot see past the blind spot. Confirm every service on the hot path emits spans before trusting the ranking.

  3. Clock skew across hosts. Cross-service durations depend on comparing timestamps from different machines. A child that appears to start before its parent, or a negative inter-service gap, is a skew artefact, not a real event ordering. Keep NTP tight and treat sub-millisecond cross-host gaps as noise, exactly as you would when debugging orphaned spans.

  4. Parallelism that is actually serial. Fan-out that looks concurrent in code can serialise at runtime — a thread pool of size one, a connection pool exhausted to a single connection, or an await inside a loop. The waterfall reveals the truth: bars that you expected to overlap instead stack end-to-end. Trust the timestamps over the source code.

  5. Retries inflating a single logical operation. A span that retries three times internally shows one wide bar with high self-time. It is on the critical path, but the fix is retry policy, not the downstream operation. Look for retry events or retry.count attributes before concluding the callee is slow.

  6. The root span self-time is the request’s own overhead. Large root self-time with fast children means the bottleneck is in the entry service itself — serialization, middleware, template rendering — not downstream. Do not go hunting in child services when the time is being spent at the top.

Performance and Scale Notes

Computing the path is cheap; fetching the trace is not. Pulling a full trace with thousands of spans over the backend’s HTTP API is the expensive step. For routine analysis, sample a handful of slow traces rather than exporting everything; for systematic latency work, prefer server-side aggregation (Tempo’s metrics-generator or Jaeger’s SPM) to rank operations before you drill into individual traces.

Very deep or very wide traces stress the UI, not the math. A trace with tens of thousands of spans — common in a fan-out that creates a span per item — will lag the waterfall renderer badly. This is itself a signal: excessive span-count is often the bug. Aggregate per-item work under a single span where semantic precision allows, as covered in the span lifecycle guidance on span cardinality.

Sampling interacts with what you can analyse. If head-based sampling dropped the slow traces you need, critical path analysis has nothing to work with. Latency-based tail sampling guarantees the P99 outliers reach storage, which is precisely the population you want to analyse. Align your sampling policy with your debugging goal, or the interesting traces will never be there when you go looking.

Aggregating self-time across traces beats single-trace intuition. One trace shows you a path; a thousand traces show you the distribution. Export critical paths in bulk and sum self-time per operation name to find where your service fleet actually spends its latency budget — that ranking survives outliers in a way a single hand-read waterfall never can.

Troubleshooting FAQ

Why is the longest span in my trace not the bottleneck?

A long span only drives request latency if it sits on the critical path. When work runs in parallel, one branch can be the longest span while a shorter branch on the critical path gates completion. The critical path is the chain of spans where reducing any one span’s duration reduces the total request time; spans off that path have slack and can grow without affecting the response.

What is the difference between self-time and wall-time on a span?

Wall-time is the span’s full duration from start to end. Self-time is the portion of that duration not covered by any child span — the time the span spent doing its own work rather than waiting on children. A span with high wall-time but near-zero self-time is just an aggregator; the real cost lives in a descendant. Optimise against self-time, not wall-time.

How do I spot an N+1 query pattern in a trace?

Look for a parent span containing many short, near-identical child spans with the same operation name, executed one after another rather than concurrently. Twenty sequential 4 ms database spans total 80 ms of serial self-time that a single batched query would collapse to one 6 ms span. Sort child spans by name and count repeats; a high repeat count with sequential timestamps is the signature.

Why do some child spans start before their parent or overlap impossibly?

This is clock skew. Each host stamps span timestamps from its own system clock, and unsynchronised clocks produce negative gaps or children that appear to start before the parent. Critical path computation that relies on raw cross-host timestamps becomes unreliable. Synchronise NTP across all hosts and treat sub-millisecond cross-service gaps as noise rather than signal.

A gap on the critical path has no span covering it — what am I missing?

Unaccounted gaps are usually uninstrumented work: a queue wait before a consumer picks up the message, a connection-pool checkout, DNS resolution, or a TLS handshake that no span wraps. The gap is real latency the trace cannot attribute. Add an explicit span around the suspected operation, or check for an async hand-off where the producer span ended before the consumer span began.

↑ Back to Trace-Based Debugging & Signal Correlation