My First Day With OpenTelemetry: Spans That Arrive but Measure Nothing

How this piece came together. A Zenn writing contest put OpenTelemetry back on my radar, and this is the record of learning it by doing — picking it up, hitting confusion, and working through the side-questions with an AI while writing it up. Every command, number, and output shown below was run and confirmed on my own machine.

I touched OpenTelemetry for the first time today. I knew the name; I'd never installed it. This is the record of adding instrumentation to a piece of my own code and seeing what actually showed up.

The short version: the first version of my instrumentation didn't work. All 15 spans arrived cleanly, with the right names and the right attributes, and they lined up in the Jaeger UI exactly as expected. I was about to call it done — until I looked at the actual numbers. The parent span read 1,006 ms. The 15 child spans summed to 0.085 ms.

The missing ~1,000 ms wasn't recorded anywhere. No error, either.

The cause was how I'd written it. I ran the work, then built spans while reading the results that came back. The child spans were timing "how fast the loop that reads results runs," not the checks themselves.

I rewrote the same logic to wrap the actual execution instead, and the same 15 children summed to 1,183 ms. Span count, names, attributes — none of that changed.

What follows is how I got there, and then — after I thought I had a way to tell a "healthy" trace from a broken one — how I broke that judgment method too, and fixed it. Some of this will be obvious to anyone who already knows this stuff; I'm writing it down as a record of what a first-timer actually gets wrong.

Environment: A Docker-less Local Setup

I don't have Docker, podman, or colima installed. Most OpenTelemetry getting-started guides assume docker compose, but both the Collector and Jaeger ship as plain binaries, so this works without any of that.

$ curl -sSL -o jaeger.tar.gz \
    https://github.com/jaegertracing/jaeger/releases/download/v2.20.0/jaeger-2.20.0-darwin-arm64.tar.gz
$ tar xzf jaeger.tar.gz && ./jaeger-2.20.0-darwin-arm64/jaeger

Jaeger v2 has a built-in OTLP receiver, so it listens on port 4317 and serves the UI on 16686.

$ curl -sS -o /dev/null -w '%{http_code}\n' http://localhost:16686/
200

The sending side is Python, with two dependencies.

$ uv add opentelemetry-sdk opentelemetry-exporter-otlp-proto-grpc

This is a setup for local experimentation, not a recommended production configuration. In production the default path is OTLP → Collector → backend. Putting a Collector in front gets you batching, retries, sampling, and the ability to swap destinations without the app ever knowing where the data actually goes. None of that is needed for what this article covers, so I skipped it — but please don't read "Jaeger alone was enough for me today" as "Jaeger alone is enough."

What I Measured

A pre-publish check for blog articles. Before an article goes out, it runs checks — topic classification, leaked sensitive information, tag rules, posting-interval limits, and so on — and stops publication if anything trips. It's Python, and calling run_gates(platform, article_path) returns a list of check results.

The Bad Example: Building Spans After the Result Comes Back

Here's what I wrote first.

with tracer.start_as_current_span("publish gate") as root:
    result = run_gates("qiita", article)          # everything actually runs here
    for c in result.checks:                        # this just reads the finished results
        with tracer.start_as_current_span(f"check: {c.id}") as s:
            s.set_attribute("outcome", c.outcome)

It looks reasonable at a glance. There's a span per check, and each one carries a name and an attribute. And Jaeger did show 15 child spans, right on cue.

But run_gates is completely finished by line 2. Everything from line 3 down is just reading results that already exist. What the span wraps is "read one result out of a list," not the check that produced it.

bad example: spans built after the fact
  parent: 1006.0 ms / sum of 15 children: 0.085 ms
    0.046 ms  check: topic_class_qiita
    0.006 ms  check: sensitive_identifiers_qiita
    0.004 ms  check: unsourced_experience_qiita

Every child comes in under 0.05 ms, and the parent is a full second. Roughly 1,006 ms isn't recorded in any span at all.

What makes this dangerous is that nothing throws an error. The SDK exports fine, Jaeger renders fine, and the trace looks complete on the screen.

The Good Example: Wrapping the Actual Execution

The fix is to start the span inside the function that actually runs, and keep it open until that function returns. For code I own, the natural way to do that is a decorator.

def traced(name=None):
    def deco(fn):
        @functools.wraps(fn)
        def wrapper(*a, **k):
            with tracer.start_as_current_span(name or fn.__name__) as s:
                try:
                    return fn(*a, **k)
                except Exception as e:
                    s.record_exception(e)
                    s.set_status(trace.Status(trace.StatusCode.ERROR, str(e)))
                    raise
        return wrapper
    return deco

@traced("check: authority verification")
def check_authority(): ...

Passing exceptions through record_exception and set_status, instead of swallowing them, is part of what makes this a workable minimum. Measuring three checks with this shape, the children summed to 100.0% of the parent.

This particular task came with the constraint "don't touch the production code," so instead I swapped in a wrapped version of the function that runs a single check, at runtime, just for the measurement.

orig = gate_runner._run_check

def wrapped(entry, *a, **k):
    with tracer.start_as_current_span(f"check: {entry.get('id')}") as s:
        r = orig(entry, *a, **k)                   # execution happens inside the span
        s.set_attribute("outcome", str(r.outcome))
        return r

gate_runner._run_check = wrapped
run_gates("qiita", article)
gate_runner._run_check = orig

This kind of runtime swap is a temporary measurement device, not something to leave in place. Its blast radius is hard to reason about, it's easy to forget to restore, and it breaks if something else swaps the same function mid-flight under concurrency. For ongoing measurement, add a decorator instead — or, if the target is a well-known library, lean on automatic instrumentation via opentelemetry-instrument. That said, automatic instrumentation only covers libraries it already has support for; your own functions aren't covered, so those still need manual instrumentation either way.

Re-measuring the same article, the same checks, the same span names, gives this:

good example: wrapping the execution
  parent: 1221.2 ms / sum of 15 children: 1183.058 ms
    644.6 ms  check: publish_authority_qiita
    538.4 ms  check: qiita_pre_publish_check_cli
      0.015 ms  check: topic_class_qiita

Parent at 1,221 ms against a child sum of 1,183 ms. The 38 ms gap is explainable — result assembly and similar overhead — and stays in a reasonable range.

And for the first time, the contents were actually visible. Of that roughly one second, 644 ms was an authority check for publishing, and 538 ms was a call into an existing check script. Together those two account for 97% of the total — a number nobody had before instrumentation existed.

Judgment Method: My First Attempt Broke Under Parallelism

Both traces have the same span count, the same names, the same attributes. Side by side in the Jaeger UI, unless you already know what you're looking for, you won't spot the difference. I wanted a number to judge by.

My first idea was: sum the child span durations, divide by the parent. On the two examples above, that separates cleanly.

bad example: spans built after the fact   0.0%
good example: wrapping the execution      96.9%

I thought that settled it — until I ran it on parallel execution, and it broke.

async def check(name, sec):
    with tracer.start_as_current_span(f"check: {name}"):
        await asyncio.sleep(sec)

with tracer.start_as_current_span("run three checks in parallel"):
    await asyncio.gather(check("A", 0.3), check("B", 0.3), check("C", 0.3))

parent 301 ms / sum of 3 children 903 ms
naive sum ÷ parent = 299.8%

With three things running at once, a plain sum comes out to roughly three times wall-clock time. Building the metric from a single sequential example was the mistake.

The fix is to collapse overlapping intervals before comparing. Sort the intervals and merge them — no new dependency needed.

def union_us(spans, parent):
    """Sum the child spans' occupied intervals, with overlaps removed (microseconds).

    Clips to the parent's own time window — otherwise a child that spills
    outside the parent can push the result past 100%.
    """
    iv = []
    for s in spans:
        a, b = s["startTime"], s["startTime"] + s["duration"]
        pa, pb = parent["startTime"], parent["startTime"] + parent["duration"]
        a, b = max(a, pa), min(b, pb)
        if b > a:
            iv.append((a, b))
    iv.sort()
    total = 0
    cur_s = cur_e = None
    for s, e in iv:
        if cur_e is None or s > cur_e:
            if cur_e is not None:
                total += cur_e - cur_s
            cur_s, cur_e = s, e
        else:
            cur_e = max(cur_e, e)
    if cur_e is not None:
        total += cur_e - cur_s
    return total

That took a detour through units. I had another model review this article's draft, and it flagged that startTime and duration are nanoseconds by spec, so naming the function union_us (microseconds) and converting to milliseconds was off by a factor of 1,000. It sounded plausible enough that I nearly "fixed" it — but I checked first.

The parent span's duration for three asyncio.sleep(0.3) calls run in parallel was 301311. As microseconds, that's 301.3 ms. As nanoseconds, it would be 0.3 ms. The code actually waits 300 ms, so microseconds is correct — the review comment was the one that was wrong.

When you're new to something and someone who sounds like they know it tells you "that's wrong," the instinct is to just go fix it. But running one case with a known, expected value and checking it against the output settles it in seconds — faster than tracking down the spec. And getting the order of magnitude wrong doesn't leave an obvious trace either: the ratio still looks correct on its face, so nothing points back to the mistake later.

Running all three cases through it:

publish gate (decorator version)     naive sum  100.0% / union 100.0%
good example: wrapping the execution naive sum   96.9% / union  96.9%
running three checks in parallel     naive sum  299.8% / union 100.0%

The union stays within 100% even under parallel execution. Fetching the trace looked like this. The same service name also returns past runs, so remember to take only the most recent one — I skipped that at first and got a "good example" that read 0.0%, because a pre-fix run was still mixed into the results.

data = json.load(urllib.request.urlopen(
    f"http://localhost:16686/api/traces?service={service}&limit=20"))["data"]

def root_of(tr):
    return [s for s in tr["spans"] if not s.get("references")][0]

latest = max(data, key=lambda tr: root_of(tr)["startTime"])
root = root_of(latest)
kids = [s for s in latest["spans"] if s.get("references")]
print(f"union / parent = {union_us(kids, root) / root['duration']:.1%}")

How Far Should I Trust This Metric?

A low number doesn't, by itself, mean "the instrumentation is broken." It also comes out low in these cases:

• The parent is carrying I/O wait. If waiting on an external API's response counts toward the parent's time and the child spans sit outside that wait, an uncovered interval remains.
• Some work was never turned into a child span. Data transformation, cache checks — anything in between that wasn't instrumented shows up only in the parent's time, never in a child's.
• The context broke across an async boundary. Cross a thread or an asyncio boundary without care and the parent-child link doesn't survive, so that work never gets tallied as a child at all.

So this metric isn't "proof the instrumentation is broken." It's closer to a prompt to go find out why, when a number looks off — not an established practice, just something I put together because I ran into this exact problem today. If it comes out near 0% and there's no I/O wait to explain it, the first thing to suspect is how the spans were built. That's exactly what happened to me here.

When You Have to Connect Things After the Fact

There are legitimate designs where a result arrives somewhere else, at some other time — batch jobs, async queues. OpenTelemetry has two mechanisms for this, but they do different jobs.

• Span Link: connects a span in another trace in as a reference. Useful for a causal-but-not-parent-child relationship — "the work that got enqueued" and "the work that consumed it," for example.
• Event: marks a specific point in time inside a span. Records something that happened along the way.

The thing to watch for: neither one stands in for measuring duration. An Event is a point, not an interval, so it can't be used to split a duration after the fact. If you want to measure time, you have to put a span where the work actually executes. A Link is for reconnecting causality after the fact — reconnecting the causal chain doesn't reconstruct the timing.

What This Article Doesn't Cover

I only measured a single local process, so this leaves out everything production actually needs:

• Sampling. Sending every span overwhelms the backend at scale; head-based vs. tail-based sampling is a real decision to make.
• Context propagation. Cross a thread or an asyncio boundary carelessly and contextvars breaks, severing the parent-child relationship.
• Running a Collector. Batching, retries, splitting destinations — the production default, and I skipped it entirely here.
• Backend persistence and auth. I used a local, unauthenticated Jaeger instance as-is.

Summary

• Building spans after processing finishes makes the duration vanish without an error. The spans still arrive, and the names and attributes are still correct.
• Wrapping the actual execution surfaces the real numbers. The same target went from 0.085 ms to 1,183 ms without any change in span count, names, or attributes.
• For ongoing measurement, a decorator or automatic instrumentation seems to be the right shape. A runtime swap is a temporary investigation tool, not something to keep.
• The judgment metric I ended up using is union of child spans ÷ parent. A naive sum hit 299.8% under parallel execution and was unusable.
• A low number means "go find the reason," not "it's broken." I/O waits and uninstrumented sections pull it down too.
• Link and Event, for connecting things after the fact, exist for causality and points in time — neither one measures duration.

Adding instrumentation makes it easy to relax, just because you "added it." But a span arriving and a span measuring the thing you actually wanted to measure turned out to be two different things. Even the metric I used to judge that difference was wrong on the first pass — built from a single example that didn't generalize.

The Limits of This Article

I wrote this without fully understanding the tool — reading the official docs and other people's write-ups, running things locally to check as I went. I expect there are places here that depart from normal practice.

What I'm least confident about:

• The "union of child spans ÷ parent" metric I used for judgment is something I built because I ran into this exact problem today — it isn't a general convention. There may be a more straightforward way to check this.
• I only looked at three ways to add instrumentation: a decorator, a runtime swap, and automatic instrumentation. Real-world practice surely has other patterns.
• I only measured a single process — sequential, and asyncio parallelism. Threads, multiple processes, and distributed environments are a different story entirely.

If something here is off, I'd like to know. Every number and every piece of code shown was run locally and the output checked against what's printed, so if you reproduce it and get something different, that difference is the interesting part.

References

• OpenTelemetry Python — Instrumentation
• OpenTelemetry Python — Automatic Instrumentation
• OpenTelemetry — Sampling
• Jaeger — Getting Started

Comments

[Swapnoneel Saha]

the metric correction from naive sum to interval union is the strongest lesson. i would add a test for nested spans and a test where a child extends past the parent, because both cases can make the ratio look healthy or exceed the boundary. a trace id and run id in the validation output would also make it easier to avoid mixing old and new runs.