You've got a distributed system. You've got Jaeger, Zipkin, or some other tracing setup. You click on a slow trace and see a waterfall of spans. Now what?
Most engineers I've seen either stare at the waterfall until something stands out, or jump straight to the database query thinking that's always the problem. Both approaches waste time. Over the last few years debugging latency in production, I've developed a systematic approach to reading traces that cuts investigation time by at least half.
The Obvious: Find the Longest Span
Yes, you should look at the span with the longest duration. But that's just the starting point. The real trick is understanding the critical path — the chain of spans that determine the total trace duration. In a trace with parallel calls, the critical path is the longest sequence of parent-child spans. Ignore spans that run concurrently with a longer sibling; they're not the bottleneck.
# Using jaeger-cli to list spans sorted by duration
jaeger-cli trace find --trace-id abc123 --sort duration desc
# Output: span 'checkout.cart.getItems' 1200ms
# span 'checkout.payment.authorize' 800ms
# span 'checkout.shipping.calc' 300msThe Non-Obvious: Gaps Between Spans
A common mistake is only looking at span durations. Often, the biggest delay is in the gaps — time not accounted for by any span. This happens when there's unmeasured work (e.g., waiting for a lock, kernel context switching, or a missing span around an HTTP call). I once spent two hours chasing a 500ms span that turned out to be a 50ms span with a 450ms gap caused by a DNS resolution that wasn't instrumented.
Add explicit spans around any I/O, even if you think it's fast. You'll be surprised how often DNS, connection pooling, or serialization eats latency.
Real-World Example: The Case of the Missing Span
The 2-Second Checkout P99
- 10:00Alert: checkout service P99 latency spikes to 2s (baseline 500ms).
- 10:05Grab a random slow trace. Waterfall shows: API gateway 2000ms, checkout 1950ms, cart 300ms, payment 400ms, shipping 50ms.
- 10:10Sum of child spans = 750ms, but parent span is 1950ms. Gap of 1200ms unaccounted for.
- 10:15Add a span around the call to an external fraud detection service (previously not traced). Now gap disappears.
- 10:20Fraud detection service was having GC pauses. Fixed by increasing heap.
Lesson
Never trust the sum of child spans equals the parent. Gaps are where latency hides. Instrument every external call.
Comparing Traces Under Load
A single slow trace can be a fluke. To find systemic latency, compare traces from high-load periods with traces from low-load periods. Look for spans that grow disproportionately under load. For example, if database query duration doubles under load but network latency stays flat, the database is the bottleneck. If network latency increases, the problem might be in the client or server TCP stack.
# Hypothetical script to compare span durations across traces
diff-traces --baseline low-load-trace.json --compare high-load-trace.json
# Output:
# span 'checkout.cart.getItems' +45% (300ms -> 435ms)
# span 'checkout.payment.authorize' +12% (800ms -> 896ms)
# gap after 'checkout.payment.authorize' +300% (50ms -> 200ms)Client vs. Server Overhead
When debugging latency in a service that calls another service, instrument both sides. I've seen cases where the client span shows 500ms, but the server span shows 200ms. The extra 300ms is client-side overhead — maybe serialization, connection pooling, or retries. Without server-side spans, you'd blame the downstream service.
Always propagate span context and record start timestamps on both sides. Without it, you can't distinguish network time from server processing time.
Sampling: Don't Lose the Slow Traces
Most tracing systems use head-based sampling (e.g., trace every 1 in 100 requests). That's fine for overall statistics, but it often misses rare slow traces. Use tail-based sampling to capture all traces whose duration exceeds a threshold (say 500ms). That way, you always have data on the worst cases. I configure Jaeger with a rate-limited sampler that captures all traces > p90 duration.
jaeger:
sampler:
type: probabilistic
param: 0.01 # 1% of all traces
tail-based-sampler:
type: rate-limiting
param: 10 # max 10 traces per second
threshold: 500ms # only capture traces slower than 500msVisual Pattern Recognition
Over time, you'll learn to spot patterns in trace waterfalls. A "staircase" pattern (each span starts after the previous ends) indicates serial processing that could be parallelized. A "fan-out" with one long span suggests a bad timeout or retry storm. A "gap" after a short span means something is missing. I keep a set of annotated screenshots of common patterns — it helps new team members ramp up faster.
The most expensive latency bug I ever fixed was hiding in a gap smaller than 10px on the waterfall. Zoom in.
Putting It All Together
- 1Open the trace and identify the critical path (longest chain of parent-child spans).
- 2Calculate the sum of child span durations and compare to parent duration. Investigate gaps.
- 3Sort spans by duration descending. Look at the top 3 longest spans.
- 4Check for missing instrumentation around external calls and add spans if needed.
- 5Compare this trace with a baseline from low-load conditions.
- 6Look at client and server spans for the same operation to isolate overhead.
Distributed tracing gives you the data, but it takes practice to read it. Start with these techniques next time you see a slow trace. You'll find the root cause faster than chasing database queries blindly.
Frequently asked questions
How do I find the slowest span in a trace?
Sort child spans by duration descending. The longest child span is usually the culprit, but also check for gaps between spans (unsampled async work).
Why do I see gaps in my trace waterfall?
Gaps often mean time spent in unsampled operations, network latency, or queue wait. Add custom spans around external calls to fill those gaps.
What sampling strategy should I use for latency debugging?
Use head-based sampling (e.g., 1% of all requests) combined with tail-based sampling that captures all traces with duration > p99. This keeps rare slow traces.