We fixed the slowest span and the response time did not move

Goal

You analyze the 3,454 spans in the Pod with the standard library only, compute self time and the critical path yourself, confirm in numbers that 'the longest span' and 'the span that needs fixing' are different, and then submit what you will fix together with the expected saving.

Why it matters

The longest bar on a waterfall view tells you only 'how long did this section take' and does not answer 'if I shorten this section, does the total shrink'. Among parallel siblings, the one that finishes first does not contribute to response time no matter how long it is. What separates the two questions is the critical path calculation, and that calculation needs only three things about a span: start time, duration, and parent identifier. If you overlay self time on top of this, the place to fix narrows, and if you group siblings with the same name, an N+1 that never made the individual ranking is revealed. The habit of writing down the expected saving as a number before fixing is the last piece — only then does it remain after deployment whether your judgment was right.

Steps

Create /root/obs-trace-critical/trace.py. When you run python3 trace.py shape, it must read /opt/lab/critpath/spans.jsonl and print six lines in the order spans=, traces=, roots=, rootless_traces=, orphan_spans=, clean_traces=. A root span is a span whose parent_id is null, an orphan span is a span whose parent_id is not in this file, and clean_traces is the number of traces with exactly one root and no orphans. Save the same six lines to /root/obs-trace-critical/01-shape.txt as well.
Add trace.py tree <trace_id>. It walks the spans of that trace depth-first from the root and prints one line per span, <깊이><탭><span_id><탭><name><탭><지속시간> (depth, tab, span_id, tab, name, tab, duration). The depth of the root is 0, and siblings are in ascending start_ms order. Write the duration to three decimal places. If given a trace with no root, it must exit with a non-zero value.
Add trace.py self <trace_id>. For each span, compute the self time (total time − the time taken by the children) and print <span_id><탭><name><탭><자기시간> (span_id, tab, name, tab, self time) for all spans in descending self time. When child intervals overlap each other, you must subtract the length of their union — if you simply add and subtract, you get a negative for a span with parallel calls. Check it with 008cde18a6503944.
Add trace.py crit <trace_id>. Pick only the spans that actually determined the root's duration and print <span_id><탭><name><탭><임계 경로 기여 밀리초> (span_id, tab, name, tab, critical path contribution in milliseconds) in descending contribution. Sweeping backward from the end of the root, skip children that end later than the current time and descend into the child that ends latest. The sum of the printed contributions must equal the root's duration — that is the check.
In the reference trace 008cde18a6503944, rank the spans excluding the root in three ways and save them to /root/obs-trace-critical/05-compare.tsv. It has three lines with no header, and each line has four tab-separated columns, <순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름> (rank, then the names ranked 1st, 2nd, and 3rd in total time, in self time, and in critical path contribution; the rank is 1, 2, or 3). Then write two lines in /root/obs-trace-critical/05-note.txt — after longest_span=, the name of the span ranked first in total time, and after longest_on_critical_path=, yes if that span is on the critical path and no otherwise.
Add trace.py nplus <trace_id>. Find groups with 5 or more of the same name lined up under the same parent and print <부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초> (parent span_id, tab, name, tab, count, tab, total milliseconds, tab, saving in milliseconds) in descending saving. Take the saving as 'when batched into a single call' and compute it as 합계 − 그중 가장 긴 하나 (the total minus the longest one among them). Then write the top group of the reference trace 008cde18a6503944 in five lines, name=, count=, total_ms=, saving_ms=, and new_root_ms=, to /root/obs-trace-critical/06-nplus.txt. new_root_ms is the root duration if that saving is fully realized.
Add trace.py pct. Sort the root durations of clean traces (one root, no orphans) in ascending order and pick p50 and p99 by nearest-rank — when the count is n, the index is ceil(q × n) − 1. The output is two lines, each <p50|p99><탭><trace_id><탭><루트 지속 시간> (p50 or p99, tab, trace_id, tab, root duration). Then compare the critical paths of the two traces and write six lines in /root/obs-trace-critical/07-p50p99.txt — p50_trace=, p50_ms=, p99_trace=, p99_ms=, only_in_p99=, only_in_p50=. For the last two lines, write the span names that appear on only one critical path, joined by commas (in ascending name order, without spaces).
Taking the reference trace 008cde18a6503944, compare three candidates and save them to /root/obs-trace-critical/08-plan.tsv. It has three lines with no header, and each line has four tab-separated columns, <id><탭><대상><탭><예상 절감 밀리초><탭><yes|no> (id, tab, target, tab, expected saving in milliseconds, tab, yes or no). The ids are a, b, and c, and the targets are, in order, making inventory.db.scan 0, making pricing.rules.eval 0, and batching db.query.item into one. For the expected saving, the first two are that span's critical path contribution and the last is the saving from step 6, and the fourth column is yes if that target is on the critical path. Then write four lines in /root/obs-trace-critical/08-decision.txt: fix= (one of a, b, c), expected_ms=, new_root_ms=, and reason= (at least 60 characters). You cannot choose a candidate whose saving is 0.

Notes

The working directory is /root/obs-trace-critical. If it does not exist, create it first.
The source is /opt/lab/critpath/spans.jsonl (JSON Lines, 3,454 lines). The script that made it is gen_spans.py in the same directory. One span line contains trace_id, span_id, parent_id, service, name, start_ms, and duration_ms, and start_ms is milliseconds from the moment that trace's root started.
The reference trace is 008cde18a6503944, and if you also look at d1272fdd4d4bfe50 as an example of a slow trace, the difference shows clearly.
For Python, use only the 3.12 standard library. pip install does not work.
Common mistake: computing self time by simply adding the children's time. If there are parallel children, you get a negative.
Common mistake: including in the statistics traces that have no root or have orphans mixed in. The totals quietly go wrong.
Traces (OpenTelemetry) · Observability primer · Instrumentation concepts · Latency (SRE Book: the four golden signals)

First count the shape of the data — rootless traces and orphan spans

Create /root/obs-trace-critical/trace.py. When you run python3 trace.py shape, it must read /opt/lab/critpath/spans.jsonl and print six lines in the order spans=, traces=, roots=, rootless_traces=, orphan_spans=, clean_traces=. A root span is a span whose parent_id is null, an orphan span is a span whose parent_id is not in this file, and clean_traces is the number of traces with exactly one root and no orphans. Save the same six lines to /root/obs-trace-critical/01-shape.txt as well.

The file is JSON Lines — one JSON per line. If you first build a dictionary keyed by span_id, the orphan check becomes the one line parent_id not in spans. The later steps add subcommands to the same file, so first set up a skeleton that chooses the subcommand with sys.argv[1].

Reconnect parents and children and attach depth

Add trace.py tree <trace_id>. It walks the spans of that trace depth-first from the root and prints one line per span, <깊이><탭><span_id><탭><name><탭><지속시간> (depth, tab, span_id, tab, name, tab, duration). The depth of the root is 0, and siblings are in ascending start_ms order. Write the duration to three decimal places. If given a trace with no root, it must exit with a non-zero value.

If you collect child lists keyed by parent identifier (kids[parent_id] = [자식들], where the placeholder is the list of children), walking becomes easy. If you use a stack instead of recursion, you must push the siblings in reverse order for the output order to be right. The trace to test with is 008cde18a6503944.

Self time — subtract overlapping children as a union

Add trace.py self <trace_id>. For each span, compute the self time (total time − the time taken by the children) and print <span_id><탭><name><탭><자기시간> (span_id, tab, name, tab, self time) for all spans in descending self time. When child intervals overlap each other, you must subtract the length of their union — if you simply add and subtract, you get a negative for a span with parallel calls. Check it with 008cde18a6503944.

If you sort the intervals by start time and join them from the front, you get the union length in one pass. A child interval can stick out beyond the parent interval, so it is safer to clip to the parent's range when counting. If you simply add the children's time at the root of this trace, it becomes larger than the root duration.

Critical path — of the parallel children, only the one that ended later counts

Add trace.py crit <trace_id>. Pick only the spans that actually determined the root's duration and print <span_id><탭><name><탭><임계 경로 기여 밀리초> (span_id, tab, name, tab, critical path contribution in milliseconds) in descending contribution. Sweeping backward from the end of the root, skip children that end later than the current time and descend into the child that ends latest. The sum of the printed contributions must equal the root's duration — that is the check.

The part of the parent's interval that no child covers is the parent's own contribution. After descending into a child, pull the 'current time' back to that child's start time and look at the next sibling. The parallel sibling that ended earlier drops out naturally in this process — the time it ended is later than the time already passed, so it gets skipped.

The three lists differ — which one should you fix to reduce the response

In the reference trace 008cde18a6503944, rank the spans excluding the root in three ways and save them to /root/obs-trace-critical/05-compare.tsv. It has three lines with no header, and each line has four tab-separated columns, <순위><탭><총시간 1·2·3위 이름><탭><자기시간 1·2·3위 이름><탭><임계경로 기여 1·2·3위 이름> (rank, then the names ranked 1st, 2nd, and 3rd in total time, in self time, and in critical path contribution; the rank is 1, 2, or 3). Then write two lines in /root/obs-trace-critical/05-note.txt — after longest_span=, the name of the span ranked first in total time, and after longest_on_critical_path=, yes if that span is on the critical path and no otherwise.

The three lists are produced directly by the three subcommands from the previous steps. You get the total time ranking from the last column of the tree output, self time from self, and critical path contribution from crit. The root is always first in total time, so leave it out when counting. If the first places of the three lists differ from each other, you calculated correctly.

N+1 — one is small but sixteen are big

Add trace.py nplus <trace_id>. Find groups with 5 or more of the same name lined up under the same parent and print <부모 span_id><탭><name><탭><개수><탭><합계 밀리초><탭><절감 밀리초> (parent span_id, tab, name, tab, count, tab, total milliseconds, tab, saving in milliseconds) in descending saving. Take the saving as 'when batched into a single call' and compute it as 합계 − 그중 가장 긴 하나 (the total minus the longest one among them). Then write the top group of the reference trace 008cde18a6503944 in five lines, name=, count=, total_ms=, saving_ms=, and new_root_ms=, to /root/obs-trace-critical/06-nplus.txt. new_root_ms is the root duration if that saving is fully realized.

If you group the sibling list by name (group[name].append(child)), you can count the groups right away. Whether the saving is fully realized at the root depends on whether that group is on the critical path — check whether those names appear in the crit output from the previous step.

The critical paths of p50 and p99 are different

Add trace.py pct. Sort the root durations of clean traces (one root, no orphans) in ascending order and pick p50 and p99 by nearest-rank — when the count is n, the index is ceil(q × n) − 1. The output is two lines, each <p50|p99><탭><trace_id><탭><루트 지속 시간> (p50 or p99, tab, trace_id, tab, root duration). Then compare the critical paths of the two traces and write six lines in /root/obs-trace-critical/07-p50p99.txt — p50_trace=, p50_ms=, p99_trace=, p99_ms=, only_in_p99=, only_in_p50=. For the last two lines, write the span names that appear on only one critical path, joined by commas (in ascending name order, without spaces).

You can get the set of names on a critical path by collecting the second column of the crit output. Compute the set difference of the two sets in both directions. In the slow trace, which of the parallel siblings ends later is swapped — so the names on the path diverge entirely.

What to fix — write the expected saving as a number

Taking the reference trace 008cde18a6503944, compare three candidates and save them to /root/obs-trace-critical/08-plan.tsv. It has three lines with no header, and each line has four tab-separated columns, <id><탭><대상><탭><예상 절감 밀리초><탭><yes|no> (id, tab, target, tab, expected saving in milliseconds, tab, yes or no). The ids are a, b, and c, and the targets are, in order, making inventory.db.scan 0, making pricing.rules.eval 0, and batching db.query.item into one. For the expected saving, the first two are that span's critical path contribution and the last is the saving from step 6, and the fourth column is yes if that target is on the critical path. Then write four lines in /root/obs-trace-critical/08-decision.txt: fix= (one of a, b, c), expected_ms=, new_root_ms=, and reason= (at least 60 characters). You cannot choose a candidate whose saving is 0.

The contribution of a span that is not on the critical path is 0 — its name does not appear in the crit output at all. new_root_ms is the root duration minus the saving of the chosen candidate. In reason=, write why that one and not the other two, citing numbers from the previous steps — you must be able to confirm after deployment whether this expectation was right.