Four teams, one slow checkout — traces, spans and time-to-culprit

Logs and dashboards are both recorded per service, so neither can say which hop of one request consumed the time — one record per hop of that single request, tied together, makes the slow hop name itself.

Scene 01

Four teams, one slow checkout

Watch
Try it
Predict
Capture

five teams, five formats — and nothing in these lines says which of them belong to the same checkout

What to watch for

Where did the time go? A customer's checkout took 3 seconds instead of 200 milliseconds, and four teams each swear their own service is fast. Watch the same slow checkout investigated three ways — first the teams' logs, then their dashboards, then the request recorded hop by hop — and watch the clock in the corner, which counts the minutes until someone can name the service responsible.

Across the top is Shopfront's checkout path: a request enters at the gateway, reaches checkout, and checkout calls cart, inventory and payments.
Below it, three ways to investigate the same 3 s checkout, side by side — the one you picked is framed, the other two are faded.
Left: five teams' log windows, each in its own format, with a rose chip on the two hosts whose clocks are off.
Middle: one dashboard card per service, each printing its own 99th-percentile latency and a verdict.
Right: the same request recorded as one bar per hop, all tied together into a single picture — that tied-together set of records is a trace, and each single bar — one service's own slice of the request, with a start and a duration — is a span.
The strip above the lanes counts how many windows the on-call engineer has to open; the clock top right is time-to-culprit (TTC), the minutes from the page firing to naming the guilty service.
Every number here is an example.

Implementation

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

Request.walk

what each service writes down as the checkout passes through

1def walk(checkout, path):
2    for service in path:
3        start = service.clock()
4        service.handle(checkout)
5        taken = service.clock() - start
6        service.own_log.append(line(start, taken))
7        service.own_numbers.record(taken)
8        hops_of(checkout).append(
9            hop(service, start, taken)
10        )

Investigator.find_slow_hop

which hop each way of looking can actually name

1def find_slow_hop(checkout, path):
2    if how == 'logs':
3        for service in path:
4            lines = read(service.own_log)
5            guess_by_timestamp(lines, checkout)
6        return cannot_say
7    if how == 'dashboards':
8        for service in path:
9            read(service.own_numbers)
10        return cannot_say
11    hops = hops_of(checkout)
12    return slowest(hops)

Investigator.cost_of_search

what the search costs as the path grows

1def cost_of_search(how, path):
2    if how == 'one recorded request':
3        open(one_screen)
4        return 1
5    work = 0
6    for service in path:
7        work += open(service.window)
8        work += learn(service.own_format)
9        work += ask(service.team)
10    return work

Sources

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

Scene 01 of 17, in the Why trace act — Per-service records can't blame a hop; one id can.. Logs and dashboards are both recorded per service, so neither can name the hop that consumed the time. One record per hop of a single request, tied together, makes the slow hop name itself.

Up next. One recorded request named the slow hop in a single screen. So what exactly gets recorded at each hop, and how do five records written on five machines become one picture?

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