Where did the latency go? — critical path and self time in a waterfall

A waterfall answers three questions at a glance — which span holds time its children do not account for, which children overlap and which wait on each other, and where there is no span at all — and only the chain that does not overlap can be shortened.

Previously

The right trace is open on screen. Reading it is a skill, not a glance — the biggest bar is usually a decoy.

Scene 14

Where did the latency go?

Watch
Try it
Predict
Capture

four bars are over a second — three of them only because they contain the fourth

What to watch for

You are holding the right trace at last — so which line of it do you actually go and fix? Watch the same 3 s checkout get read in four passes. First the bars alone. Then each bar split into the part it spent waiting inside a child and the part it held itself — scene 02 described that second part in plain words and deliberately did not name it; here it gets its name, self time. Then the one chain of spans that each had to wait for the next gets ringed. Then 200 identical calls to the legacy ledger service fold into a single row.

One request, every span it recorded, on one time axis: gateway at the top, then checkout, then checkout's calls to cart, inventory and payments, then payments' calls to fraud-check and to the legacy ledger service.
Inside each bar, the solid part is its self time — the milliseconds that span held that its own children do not account for; the hatched part is time it sat waiting inside a child.
The primary-coloured ring marks the critical path: the longest chain of spans that each had to wait for the one below it, which is the only chain whose length the request's duration depends on.
A row badged ×200 is 200 identical spans folded into one — k short sibling calls to the same peer with the same operation name, which is the N+1 pattern.
A dashed slate row is not a slow span — it is the absence of one.
The right-hand readout prints the request total, the length of that chain, and the widest bar that is not on it; the clock top right is time-to-culprit (TTC), the minutes from the page firing to naming the guilty service and operation.
Every number is an example.

Implementation

Highlighted lines are the ones running in the diagram right now.

Span.self_time

duration minus the union of the children's intervals

1def self_time(span):
2    covered = 0
3    cursor = span.start_ms
4    for child in sort_by_start(span.children):
5        if child.end_ms <= cursor:
6            continue
7        covered += child.end_ms - max(child.start_ms, cursor)
8        cursor = child.end_ms
9    return span.duration_ms - covered

Trace.critical_path

walk back from the end, last-finishing child each step

1def critical_path(span, ends_at):
2    chain = [span]
3    cursor = ends_at
4    for child in sort_by_finish(span.children, reverse=True):
5        if child.end_ms > cursor:
6            continue
7        chain += critical_path(child, child.end_ms)
8        cursor = child.start_ms
9    return chain

Viewer.collapse_repeats

same operation, same peer, k times — one row

1def collapse_repeats(siblings, fold_repeats):
2    key_of = lambda s: (s.name, s.peer)
3    rows = []
4    for key, group in group_by(siblings, key_of):
5        if not fold_repeats or len(group) < FOLD_MIN:
6            rows += group
7            continue
8        first = min(s.start_ms for s in group)
9        last = max(s.end_ms for s in group)
10        rows.append(fold(key, first, last - first,
11                         badge=f'×{len(group)}'))
12    return rows

Sources

Where this sits in Build a distributed tracing system (Jaeger / Zipkin style)

Scene 14 of 17, in the Store & read act — Key by trace id, find it, read it, distrust it.. The waterfall answers three questions at a glance: which span holds time its children don't account for, which children overlap, and where there is no span at all. Only the chain that doesn't overlap can be shortened.

Up next. You named a culprit from the shape of the bars. Can you trust the bars?

All 17 scenes in Build a distributed tracing system (Jaeger / Zipkin style) · Every curriculum

Built with Arqly

Every scene in Build a distributed tracing system (Jaeger / Zipkin style) builds on the one before it.All 17 Build a distributed tracing system (Jaeger / Zipkin style) scenes