TT Lab
Get started
Learn Learning paths Courses

Where Distributed Tracing Breaks

One span tells you nothing, thirty spans nobody reads

Continue in TT Lab

Goal

You learn how to decide, with numbers, where to draw boundaries, by putting spans by hand into order-processing code that has not a single line of instrumentation. You measure the instrumentation gap, fold repetition into attributes, write that judgment in a rules file, and apply it as it is to a second handler.

Why it matters

If you put only one span, the trace says nothing but "it took 211 milliseconds." If you create a span in every loop iteration, this time thirty same-shaped bars run on and nobody looks to the end. Both failures come from skipping the same question — what will we ask of this trace later. The tool that finds the places that answer that question is the instrumentation gap. The time in the parent interval that no child covers is exactly "time we do not yet know about," and that place is where the next span should be drawn. Conversely, repetition must be folded into a count, a total time, and a maximum rather than spans, so that the trace stays at a readable size. Finally, if you leave this judgment to personal taste you will fight over it again at every review, so you write the span cap per request and the allowed gap in a file and have a machine read it.

Steps

  1. Create /root/tp-boundary/01_root.py. Using provider from /opt/app/tracelab/dump.py, make a provider with the service name shop-api, reading the dump path first from the environment variable TRACELAB_OUT and, if it is absent, using /root/tp-boundary/01-root.jsonl. Inside one SERVER span named POST /checkout, call validate → load_cart → price_of (for all products) → charge → write_receipt from tracelab.tp_boundary.shop in order, and call flush() at the end. Then run it with /opt/otel-lab/bin/python to produce the dump, and write two lines, spans= and root_ms=, in /root/tp-boundary/01-root.txt (the values exactly as read from the dump).
  2. Create /root/tp-boundary/02_split.py. Same as step 1, but wrap the database round trip load_cart in a cart.load span and the outgoing charge in a payment.charge span (these two are the places auto-instrumentation would create for you). The default dump path is /root/tp-boundary/02-split.jsonl. After running it, write four lines, root_ms=, covered_ms=, gap_ms=, and gap_ratio=, in /root/tp-boundary/02-gap.txt. covered_ms is the length of the root's child intervals added as a union, and gap_ratio is (root − covered time) ÷ root, written to four decimal places.
  3. Create /root/tp-boundary/03_close.py. To eliminate the gap left in step 2, wrap validate in an order.validate span, the entire product price lookup repetition in price.lookup, and write_receipt in a receipt.write span. Match the span names exactly to these five (order.validate, cart.load, price.lookup, payment.charge, and receipt.write) plus the root POST /checkout. The default dump path is /root/tp-boundary/03-close.jsonl. After running it, write the same four lines as in step 2 in /root/tp-boundary/03-gap.txt, and make gap_ratio come out below 0.05.
  4. Create /root/tp-boundary/04_peritem.py. Same as step 3, but inside price.lookup, create one price.item span each time you look up one product. The default dump path is /root/tp-boundary/04-peritem.jsonl. After running it, write three lines, spans_per_request=, item_spans=, and spans_per_1000_requests=, in /root/tp-boundary/04-count.txt. The last line is the number of spans per request multiplied by 1000, as an integer.
  5. Create /root/tp-boundary/05_fold.py. Remove the price.item spans, and instead attach three attributes to the price.lookup span: price.lookup.count (the number of lookups), price.lookup.total_ms (the total in milliseconds), and price.lookup.max_ms (the milliseconds of the single longest case). Then record the product that took longest as an event named price.lookup.slowest, putting sku in the event attributes. The default dump path is /root/tp-boundary/05-fold.jsonl, and the total number of spans must not exceed 8.
  6. Create /root/tp-boundary/06_kind.py. Same as step 5, but state SpanKind explicitly on every span — incoming requests are SERVER, calls going out of the process (cart.load, payment.charge, and receipt.write) are CLIENT, and intervals split inside the process (order.validate and price.lookup) are INTERNAL. The default dump path is /root/tp-boundary/06-kind.jsonl, and after running it, write one line per span in /root/tp-boundary/06-kinds.tsv as <스팬이름><탭><kind> (the placeholders are the span name, a tab, and the kind), in order of start time (six lines with no header).
  7. Write three lines in /root/tp-boundary/budget.txt — max_spans_per_request=8, max_gap_ratio=0.10, and root_kind=SERVER. Then create /root/tp-boundary/check_budget.py. When called as python3 check_budget.py <규칙파일> <덤프> (the placeholders are the rules file and the dump), it prints one line VIOLATION <규칙키> <지금 값> (the placeholders are the rule key and the current value) for each broken rule and exits with code 1, and if all are kept it prints one line starting with OK and exits with code 0. Finally, write three lines in /root/tp-boundary/07-verdict.tsv — each line is <덤프파일이름><탭><pass|fail><탭><깨진 규칙키 또는 -> (the placeholders are the dump file name, a tab, pass or fail, a tab, and the broken rule key or a dash), and they are the results of checking 02-split.jsonl, 04-peritem.jsonl, and 06-kind.jsonl in this order.
  8. Create /root/tp-boundary/08_search.py and instrument the GET /search handler from scratch. Call shop.parse_query → shop.search_index → shop.hydrate for each result → shop.render in that order, and the spans are four under the root GET /search (SERVER): query.parse (INTERNAL), index.search (CLIENT), result.hydrate (INTERNAL), and response.render (INTERNAL). Fold the repetition and attach result.hydrate.count, result.hydrate.total_ms, and result.hydrate.max_ms to result.hydrate as attributes. The default dump path is /root/tp-boundary/08-search.jsonl, and when you run the step 7 checker on this dump, OK must come out.

Notes

Start with a one-span trace

Create /root/tp-boundary/01_root.py. Using provider from /opt/app/tracelab/dump.py, make a provider with the service name shop-api, reading the dump path first from the environment variable TRACELAB_OUT and, if it is absent, using /root/tp-boundary/01-root.jsonl. Inside one SERVER span named POST /checkout, call validate → load_cart → price_of (for all products) → charge → write_receipt from tracelab.tp_boundary.shop in order, and call flush() at the end. Then run it with /opt/otel-lab/bin/python to produce the dump, and write two lines, spans= and root_ms=, in /root/tp-boundary/01-root.txt (the values exactly as read from the dump).

The system python3 does not have OpenTelemetry. Always run the instrumented program with the Python that has otel in it. The dump is append-only, so if you run it twice into the same file, spans pile up — delete it before running again. To look at the dump with human eyes, python3 /opt/app/tracelab/tp_boundary/gapstat.py tree <덤프> (the placeholder is the dump) is handy.

Add only the two spans auto-instrumentation gives and measure the gap

Create /root/tp-boundary/02_split.py. Same as step 1, but wrap the database round trip load_cart in a cart.load span and the outgoing charge in a payment.charge span (these two are the places auto-instrumentation would create for you). The default dump path is /root/tp-boundary/02-split.jsonl. After running it, write four lines, root_ms=, covered_ms=, gap_ms=, and gap_ratio=, in /root/tp-boundary/02-gap.txt. covered_ms is the length of the root's child intervals added as a union, and gap_ratio is (root − covered time) ÷ root, written to four decimal places.

/opt/app/tracelab/tp_boundary/gapstat.py has load, root_span, children, union_ns, and ms. The reason for a union is that children can overlap — if you count an overlapping interval twice, the covered time becomes longer than the parent. It is normal for the gap to come out at nearly half at this step.

Split the intervals with big gaps and bring it below 5%

Create /root/tp-boundary/03_close.py. To eliminate the gap left in step 2, wrap validate in an order.validate span, the entire product price lookup repetition in price.lookup, and write_receipt in a receipt.write span. Match the span names exactly to these five (order.validate, cart.load, price.lookup, payment.charge, and receipt.write) plus the root POST /checkout. The default dump path is /root/tp-boundary/03-close.jsonl. After running it, write the same four lines as in step 2 in /root/tp-boundary/03-gap.txt, and make gap_ratio come out below 0.05.

The key is to wrap all twenty-four repetitions in one span — at this step you still do not create a span for each repetition. The gap will not become 0. Starting and ending a span itself uses a few microseconds. As a ratio, it is a negligible size.

Count how many spans you get if you create one per repetition

Create /root/tp-boundary/04_peritem.py. Same as step 3, but inside price.lookup, create one price.item span each time you look up one product. The default dump path is /root/tp-boundary/04-peritem.jsonl. After running it, write three lines, spans_per_request=, item_spans=, and spans_per_1000_requests=, in /root/tp-boundary/04-count.txt. The last line is the number of spans per request multiplied by 1000, as an integer.

Fill in all three lines by counting directly from the dump. The cart size is fixed by CART_SIZE in /opt/app/tracelab/tp_boundary/shop.py. If this is the number with twenty-four products, work out in your head how many it would be for an order with two hundred products — that is the reason for the next step.

Fold the repetition into attributes and an event instead of spans

Create /root/tp-boundary/05_fold.py. Remove the price.item spans, and instead attach three attributes to the price.lookup span: price.lookup.count (the number of lookups), price.lookup.total_ms (the total in milliseconds), and price.lookup.max_ms (the milliseconds of the single longest case). Then record the product that took longest as an event named price.lookup.slowest, putting sku in the event attributes. The default dump path is /root/tp-boundary/05-fold.jsonl, and the total number of spans must not exceed 8.

Measure the duration of a single case yourself with time.perf_counter(). If you keep only the average, the fact that one out of twenty-four was ten times slower disappears — so keep the maximum separately, and write what that case was as an event, a record that has a point in time. An event is span.add_event(이름, {속성}) (the placeholders are the name and the attributes).

Mark the boundaries with SpanKind

Create /root/tp-boundary/06_kind.py. Same as step 5, but state SpanKind explicitly on every span — incoming requests are SERVER, calls going out of the process (cart.load, payment.charge, and receipt.write) are CLIENT, and intervals split inside the process (order.validate and price.lookup) are INTERNAL. The default dump path is /root/tp-boundary/06-kind.jsonl, and after running it, write one line per span in /root/tp-boundary/06-kinds.tsv as <스팬이름><탭><kind> (the placeholders are the span name, a tab, and the kind), in order of start time (six lines with no header).

CLIENT and INTERNAL become the criterion for separating "the time we waited on others" from "the time we worked" later. A database round trip is also a call going out of the process, so it is CLIENT. If you build the tsv by extracting it straight from the dump, you cannot make a mistake by typing it by hand.

Write the boundary rules in a file and build a checker

Write three lines in /root/tp-boundary/budget.txt — max_spans_per_request=8, max_gap_ratio=0.10, and root_kind=SERVER. Then create /root/tp-boundary/check_budget.py. When called as python3 check_budget.py <규칙파일> <덤프> (the placeholders are the rules file and the dump), it prints one line VIOLATION <규칙키> <지금 값> (the placeholders are the rule key and the current value) for each broken rule and exits with code 1, and if all are kept it prints one line starting with OK and exits with code 0. Finally, write three lines in /root/tp-boundary/07-verdict.tsv — each line is <덤프파일이름><탭><pass|fail><탭><깨진 규칙키 또는 -> (the placeholders are the dump file name, a tab, pass or fail, a tab, and the broken rule key or a dash), and they are the results of checking 02-split.jsonl, 04-peritem.jsonl, and 06-kind.jsonl in this order.

For the gap calculation, just use the functions in /opt/app/tracelab/tp_boundary/gapstat.py as they are. The reason for keeping the rules file separate is that if you hard-code the caps in the code, you fight over them again as a matter of personal taste at every review. Two of the three dumps break different rules — first guess which one breaks what, and then run it.

Instrument a second handler with the same rules

Create /root/tp-boundary/08_search.py and instrument the GET /search handler from scratch. Call shop.parse_query → shop.search_index → shop.hydrate for each result → shop.render in that order, and the spans are four under the root GET /search (SERVER): query.parse (INTERNAL), index.search (CLIENT), result.hydrate (INTERNAL), and response.render (INTERNAL). Fold the repetition and attach result.hydrate.count, result.hydrate.total_ms, and result.hydrate.max_ms to result.hydrate as attributes. The default dump path is /root/tp-boundary/08-search.jsonl, and when you run the step 7 checker on this dump, OK must come out.

Follow the order you learned in the previous seven steps — a span at every process boundary, split the intervals with big gaps, and fold repetition. The number of search results is fixed by SEARCH_HITS in shop.py. If the checker prints VIOLATION, fix the instrumentation, not the rules.