Agent Traces Hide Their Gaps: Build a Span-Gap Ledger

A trace that draws every span can still fail to explain a run. Take the wall clock of the root span, subtract the exclusive time of every span beneath it, and whatever remains is the part of the run nobody instrumented. That residual is usually where the bug lives, and no waterfall view will point at it, because a waterfall only draws what it was given.

Take a synthetic turn to make the arithmetic concrete: a root span of 1840 ms, one model call of 190 ms, two tool calls of 8 ms and 2 ms. Roughly 1.6 seconds are unaccounted for. That time did not vanish. It went into a control loop that polls, an HTTP client redoing TLS, a retry sleeping before it re-issues a request, or a serializer walking a large payload. None of those emit spans by default, so none of them appear.

Exclusive time is the concept the ledger is built on. For any span, exclusive time is its duration minus the union of its direct children's intervals. A parent that waits 300 ms while a child runs 120 ms has 180 ms of exclusive time, and that 180 ms is a mixture of real work and empty waiting. The ledger separates the two by listing the covered intervals and the holes between them.

The invariant worth asserting

For a strictly nested trace, where every child sits inside its parent and siblings never overlap, exclusive time sums to the root duration exactly:

wall_clock == sum over all spans s of (duration(s) - union(direct children of s))

The identity telescopes: every non-root span is subtracted once from its parent and added once on its own line. A residual under this assumption is not rounding noise, it is a topology defect. Overlapping siblings, a child whose interval escapes its parent, or timestamps taken from two unsynchronized clocks all break the identity, and each of them means your trace is lying to you before you even start interpreting it.

That is why the ledger prints the residual next to the wall clock instead of burying it. If you run tools in parallel on purpose, the residual is the overlap you asked for and you should compare it against the overlap you expect. If you did not, stop and fix the topology first.

The ledger, in one file

The script below has no dependencies outside the standard library. It reads an OTLP/JSON export or a flat JSON list of spans, builds the parent/child index, and emits one row per span and one row per gap.

#!/usr/bin/env python3
"""span_gap_ledger.py - account for every millisecond of one agent run.

Input: OTLP/JSON (resourceSpans -> scopeSpans -> spans) or a flat JSON list.
Output: exclusive span time plus empty stretches inside each span.
"""
import json
import sys
from dataclasses import dataclass


@dataclass
class Span:
    sid: str
    parent: str
    name: str
    start: int  # ns
    end: int    # ns

    @property
    def dur(self) -> int:
        return self.end - self.start


def load(path):
    doc = json.load(open(path))
    if isinstance(doc, list):
        blocks = [{"scopeSpans": [{"spans": doc}]}]
    else:
        blocks = doc.get("resourceSpans", [doc])
    spans = []
    for rs in blocks:
        scopes = rs.get("scopeSpans") or rs.get("instrumentationLibrarySpans") or []
        for ss in scopes:
            for s in ss.get("spans", []):
                spans.append(Span(s["spanId"], s.get("parentSpanId") or "",
                                  s["name"], int(s["startTimeUnixNano"]),
                                  int(s["endTimeUnixNano"])))
    return spans


def index(spans):
    children = {s.sid: [] for s in spans}
    for s in spans:
        children.setdefault(s.parent, []).append(s)
    roots = children.get("", [])
    if not roots:
        raise SystemExit("no root span found; export the full trace")
    return children, max(roots, key=lambda s: s.dur)


def merge(intervals):
    out = []
    for a, b in sorted(intervals):
        if out and a <= out[-1][1]:
            out[-1][1] = max(out[-1][1], b)
        else:
            out.append([a, b])
    return out


def ledger(root, children):
    rows = []

    def visit(span, depth):
        clipped = []
        for c in children.get(span.sid, ()):
            a, b = max(c.start, span.start), min(c.end, span.end)
            if b > a:
                clipped.append((a, b))
        covered = merge(clipped)
        own = span.dur - sum(b - a for a, b in covered)
        rows.append({"kind": "span", "owner": span.name, "depth": depth,
                     "offset_ms": (span.start - root.start) / 1e6,
                     "ms": own / 1e6})
        cursor = span.start
        for a, b in covered:
            if a > cursor:
                rows.append({"kind": "gap", "owner": span.name, "depth": depth,
                             "offset_ms": (cursor - root.start) / 1e6,
                             "ms": (a - cursor) / 1e6})
            cursor = max(cursor, b)
        if span.end > cursor:
            rows.append({"kind": "gap", "owner": span.name, "depth": depth,
                         "offset_ms": (cursor - root.start) / 1e6,
                         "ms": (span.end - cursor) / 1e6})
        for c in sorted(children.get(span.sid, ()), key=lambda s: s.start):
            visit(c, depth + 1)

    visit(root, 0)
    return rows

The driver and a self-test that proves the identity without needing an agent:

def self_test():
    ms = 1_000_000
    spans = [Span("r", "", "agent.run", 0, 1000 * ms),
             Span("c", "r", "llm.plan", 100 * ms, 400 * ms),
             Span("g", "c", "tool.http_fetch", 150 * ms, 250 * ms)]
    children = {s.sid: [] for s in spans}
    for s in spans:
        children.setdefault(s.parent, []).append(s)
    rows = ledger(spans[0], children)
    total = sum(r["ms"] for r in rows if r["kind"] == "span")
    assert abs(total - 1000.0) < 1e-9, total
    print(f"invariant holds: {total:.1f} ms exclusive == 1000.0 ms wall clock")


def main(argv):
    if len(argv) > 1 and argv[1] == "--self-test":
        return self_test()
    spans = load(argv[1])
    children, root = index(spans)
    rows = ledger(root, children)
    own = sum(r["ms"] for r in rows if r["kind"] == "span")
    wall = root.dur / 1e6
    print(f"wall clock   {wall:9.1f} ms")
    print(f"exclusive S  {own:9.1f} ms")
    print(f"residual     {wall - own:9.1f} ms  (overlap, escaping spans, or clock skew)")
    print("\ntop gaps")
    gaps = sorted((r for r in rows if r["kind"] == "gap"), key=lambda r: -r["ms"])
    for r in gaps[:8]:
        print(f"  {r['ms']:8.1f} ms  t+{r['offset_ms']:8.1f}  "
              f"{'  ' * r['depth']}{r['owner']}")


if __name__ == "__main__":
    main(sys.argv)

Run it against a real export with python span_gap_ledger.py trace.json, or against the built-in fixture with python span_gap_ledger.py --self-test. The rows are plain dicts, so feeding the CI check below is one json.dump away.

Reading the top of the list

Sorted descending, the gaps form a budget you can act on. A synthetic example, not a measurement of any product:

     412.3 ms  t+  211.0  agent.run
      96.1 ms  t+  520.4    tool.shell_exec
      31.7 ms  t+ 1188.9    llm.plan
       8.4 ms  t+ 1402.2    tool.http_fetch
       0.3 ms  t+   12.9  agent.run

Each row names the span whose exclusive time contains the hole, and that owner tells you which layer to look at. A gap inside agent.run is the orchestrator itself: loop bookkeeping, prompt assembly, JSON serialization of a large tool result. A gap inside llm.plan is the provider client: retry backoff, connection setup, token counting done locally. A gap inside tool.* is the tool's own runtime, which often means a subprocess or an HTTP client doing work the tool never bracketed.

The decision rule for instrumentation stays narrow. Add a span only when a gap corresponds to a named unit of work you would want to debug on its own, and leave pure latency alone. Wrapping every wait in a span inflates the trace, slows the collector, and gives you a list of spans named sleep that nobody reads. One gap of 412 ms with a clear owner beats forty spans that restate it.

Turning the ledger into a regression check

Gap analysis is most useful as a diff between two runs of the same scenario. Compare the largest gap before and after a change; if it moved to a different owner, the change relocated the latency rather than removing it.

# ci_gap_diff.py - fail when the biggest gap moves or grows
import json
import sys


def top_gap(path):
    rows = json.load(open(path))
    gaps = [r for r in rows if r["kind"] == "gap"]
    return max(gaps, key=lambda r: r["ms"], default={"owner": None, "ms": 0.0})


before, after = top_gap(sys.argv[1]), top_gap(sys.argv[2])
drift = after["ms"] - before["ms"]
if after["owner"] != before["owner"] or drift > 250:  # a policy, not a law
    print(f"top gap moved: {before['owner']} {before['ms']:.1f}ms -> "
          f"{after['owner']} {after['ms']:.1f}ms")
    sys.exit(1)

The 250 ms threshold is a starting policy tuned to the noise floor of your environment, not a universal constant. On a quiet machine, single-process, sub-millisecond gaps are scheduling jitter and should be filtered out entirely.

Where a free tier fits the loop

Reproducing a run costs tokens, and the ledger step costs almost nothing because it is pure integer arithmetic over a JSON file. That split matters for anyone rebuilding a debug loop on a side project. MonkeyCode offers free model access and a free server option (availability stated by the operator), which makes the expensive half of the loop — re-running the agent to capture a fresh trace — cheap enough to do repeatedly, while the ledger runs wherever your agent already writes its spans.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

If you want to test the loop end to end, pick one failing run, generate a second trace after a fix, and check whether the top gap moved owners. That single comparison tells you more than another hour of reading span names.

What the ledger cannot tell you

It measures time, not correctness. A fully accounted run can still be wrong, and a run with a huge gap can be perfectly healthy because the gap is a third-party API you cannot instrument.

Timestamps are the weak point. Nanosecond fields written by different processes, containers, or hosts come from different clocks, and unsynchronized clocks manufacture gaps that never happened. Keep ledger comparisons within a single process with a monotonic clock until you have verified sync across the boundary.

Sampling invalidates everything. If the run was sampled below 100%, the ledger describes the sample, not the run, and the totals are fiction. Force full capture on the specific run you are debugging. Suspended runs are a second trap: an agent paused for human approval produces one giant gap that is neither a bug nor missing instrumentation, so annotate or exclude it before sorting.

Finally, some teams should skip this. If you already run a mature APM with per-service latency budgets and alerting, the ledger is a debugging tool, not a replacement, and it will mostly restate what you have. If your workload is a single-threaded script with no spans, a profiler answers the same question in one command. The ledger earns its keep in the middle: multi-step agent runs where the wall clock and the span tree disagree, and nobody knows which one to believe.