When the picture itself lies — clock skew, gaps and the uninstrumented hop

Every span's times come from the clock of the machine that recorded it and those clocks disagree, so viewers quietly shift timestamps to make a child fit inside its parent — and an empty gap has at least five possible causes that nothing in the data distinguishes.

Previously

Self time and the critical path are read off timestamps, and off the spans that happen to be there. Both of those assumptions are worth checking.

Scene 14a

When the picture itself lies

Watch
Try it
Predict
Capture

What to watch for

Can you trust the shape of a trace? Every span's start and end are stamped by the clock of the machine that recorded it, and machines in a fleet do not agree about what time it is — plain time synchronisation leaves tens of milliseconds of disagreement, which is wider than plenty of spans you care about. Watch the same two spans of one call drawn twice: once with the numbers the two machines actually reported, then once after the viewer quietly repairs them.

Two bars from one call, zoomed in so tens of milliseconds are wide on screen: checkout's client span for POST /pay on top, payments' server span for the same call underneath. checkout timestamped the top bar from its own machine's clock; payments timestamped the bottom bar from a different machine's clock, and those two clocks do not agree — that disagreement is clock skew.
The dashed box on the child's row is the gap: elapsed time no span covers.
The right-hand panel reports how far payments' clock is off, what is really in the gap, and (once corrected) how many milliseconds the viewer moved the child — that move is a skew adjustment.

Implementation

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

Tracer.finish_span

each span is stamped by the clock of the host that ran it

1def finish_span(span):
2    span.start_time = local_clock.now() - span.elapsed
3    span.end_time = local_clock.now()
4    span.process.tags['ip'] = host_ip
5    exporter.export(span)

Adjuster.adjust_trace

cross-host children only; every shift lands in the warnings

1def adjust_trace(trace):
2    for child in trace.spans:
3        parent = trace.by_id[child.parent_id]
4        if host_of(child) == host_of(parent):
5            continue
6        delta = calculate_delta(child, parent)
7        if delta == 0:
8            continue
9        child.start += delta
10        child.warnings.append(
11            f'shifted {delta}ms for clock skew'
12        )

Adjuster.calculate_delta

assumes the child nests, and the round trip splits evenly

1def calculate_delta(child, parent):
2    if child.duration > parent.duration:
3        return parent.start - child.start
4    if (child.start >= parent.start
5            and child.end <= parent.end):
6        return 0
7    latency = (parent.duration - child.duration) / 2
8    return parent.start + latency - child.start

Viewer.explain_gap

what the viewer can say about time no span covers

1def explain_gap(prev, next):
2    gap_ms = next.start - prev.end
3    candidates = [
4        'the two spans are genuinely adjacent',
5        'queue or scheduler wait',
6        'a hop nobody instrumented',
7        'a span dropped or not yet arrived',
8        'network, TLS, serialization',
9        'a stop-the-world pause',
10    ]
11    return Gap(gap_ms, cause=UNKNOWN,
12               candidates=candidates)

Sources

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

Scene 14a of 17, in the Store & read act — Key by trace id, find it, read it, distrust it.. Every span's times come from the clock of the machine that recorded it, and those clocks disagree. Viewers quietly shift timestamps to make a child fit its parent, folding real network and queue wait into the parent.

Up next. One trace can mislead you in ways you cannot detect from inside it. A million traces average that out — so what can you build from all of them at once?

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