An agent run that lasts eight seconds is not an eight-second tool. The number that should gate a retry, a budget, or a claim that the loop did engineering work is the untraced remainder: wall-clock duration minus the union of closed spans, after children have been subtracted from parents. Everything else is a mood.
Most debug loops still print elapsed time and move on. That figure mixes model wait, overlapping tools, process startup, and gaps where the tracer was not listening. Treat it as cost and you will “optimize” a parallel read that was already cheap, or miss a two-second hole where the model sat idle with no span at all.
Inclusive duration is a nested Russian doll. A parent span that wraps a plan step and three tools will report the whole doll. Sum those parents with their children and you double-count the inner work. Parallel tools make it worse: two 400 ms reads that overlap are not 800 ms of exclusive machine time. They are closer to 400 ms of wall and 800 ms of billed tool occupancy, and those are different questions.
A restaurant bill is a fair analogy. Summing dish prices ignores tax, shared plates, and the twenty minutes you waited for a table. Wall-clock is the evening. Inclusive span sum is every dish counted with the table time glued on. Exclusive span math is the only way to see what each course actually occupied.
The contract is small. Every span must have a start, an end, a parent id or a root, and a kind that is either model or tool. If end_ms is missing, the run is not closed. If two siblings overlap, their inclusive times must not be added. If the union of all intervals is much smaller than the process lifetime, the remainder is untraced work, not a rounding error.
The artifact below is a single-file judge. It is a proposal you can run locally; it is not a production tracer. Feed it a JSON run, and it prints exclusive durations, overlap pairs, and the untraced remainder as a fraction of wall-clock.
#!/usr/bin/env python3
"""exclusive_span.py — attribute agent time after exclusive span math."""
from __future__ import annotations
import json
import sys
from dataclasses import dataclass
from typing import Iterable
@dataclass(frozen=True)
class Span:
span_id: str
parent_id: str | None
kind: str
name: str
start_ms: int
end_ms: int
@property
def inclusive_ms(self) -> int:
return self.end_ms - self.start_ms
def load_run(path: str) -> tuple[int, int, list[Span]]:
with open(path, encoding="utf-8") as fh:
raw = json.load(fh)
spans = []
for row in raw["spans"]:
if row.get("end_ms") is None:
raise ValueError(f"unclosed span {row.get('span_id')}")
if row["end_ms"] < row["start_ms"]:
raise ValueError(f"inverted span {row['span_id']}")
spans.append(
Span(
span_id=row["span_id"],
parent_id=row.get("parent_id"),
kind=row["kind"],
name=row["name"],
start_ms=int(row["start_ms"]),
end_ms=int(row["end_ms"]),
)
)
return int(raw["started_at_ms"]), int(raw["ended_at_ms"]), spans
def children_of(spans: list[Span], parent_id: str) -> list[Span]:
return [s for s in spans if s.parent_id == parent_id]
def exclusive_ms(span: Span, spans: list[Span]) -> int:
kids = children_of(spans, span.span_id)
covered = union_ms((k.start_ms, k.end_ms) for k in kids)
clipped = 0
for a, b in covered:
lo = max(a, span.start_ms)
hi = min(b, span.end_ms)
if hi > lo:
clipped += hi - lo
return span.inclusive_ms - clipped
def union_ms(intervals: Iterable[tuple[int, int]]) -> list[tuple[int, int]]:
ordered = sorted(intervals)
if not ordered:
return []
out = [ordered[0]]
for start, end in ordered[1:]:
last_s, last_e = out[-1]
if start <= last_e:
out[-1] = (last_s, max(last_e, end))
else:
out.append((start, end))
return out
def overlap_pairs(spans: list[Span]) -> list[tuple[str, str, int]]:
pairs = []
for i, a in enumerate(spans):
for b in spans[i + 1 :]:
if a.parent_id != b.parent_id:
continue
lo = max(a.start_ms, b.start_ms)
hi = min(a.end_ms, b.end_ms)
if hi > lo:
pairs.append((a.span_id, b.span_id, hi - lo))
return pairs
def remainder_ms(start: int, end: int, spans: list[Span]) -> int:
covered = union_ms((s.start_ms, s.end_ms) for s in spans)
covered_total = sum(b - a for a, b in covered)
return max(0, (end - start) - covered_total)
def report(path: str) -> None:
start, end, spans = load_run(path)
wall = end - start
rem = remainder_ms(start, end, spans)
print(f"wall_ms={wall}")
print(f"untraced_ms={rem} fraction={rem / wall if wall else 0:.3f}")
for span in spans:
print(
f"{span.span_id} kind={span.kind} name={span.name} "
f"inclusive={span.inclusive_ms} exclusive={exclusive_ms(span, spans)}"
)
for a, b, ms in overlap_pairs(spans):
print(f"overlap {a} {b} ms={ms}")
model_ex = sum(exclusive_ms(s, spans) for s in spans if s.kind == "model")
tool_ex = sum(exclusive_ms(s, spans) for s in spans if s.kind == "tool")
print(f"exclusive_model_ms={model_ex} exclusive_tool_ms={tool_ex}")
if rem / wall > 0.25 if wall else False:
print("FAIL: untraced remainder exceeds 25% of wall-clock")
sys.exit(2)
if tool_ex == 0 and wall > 0:
print("FAIL: no exclusive tool time; this run is a chat, not a tool loop")
sys.exit(3)
if __name__ == "__main__":
if len(sys.argv) != 2:
sys.stderr.write("usage: exclusive_span.py run.json\n")
sys.exit(1)
report(sys.argv[1])
A fixture makes the failure mode obvious. The process lives 8400 ms. Tools overlap. A 1800 ms gap has no span. Inclusive sums look busy. Exclusive math does not.
{
"run_id": "demo-8400",
"started_at_ms": 0,
"ended_at_ms": 8400,
"spans": [
{"span_id": "m1", "parent_id": null, "kind": "model", "name": "plan",
"start_ms": 50, "end_ms": 2100},
{"span_id": "t1", "parent_id": "m1", "kind": "tool", "name": "read_a",
"start_ms": 2200, "end_ms": 2650},
{"span_id": "t2", "parent_id": "m1", "kind": "tool", "name": "read_b",
"start_ms": 2300, "end_ms": 2700},
{"span_id": "m2", "parent_id": null, "kind": "model", "name": "revise",
"start_ms": 4500, "end_ms": 6200},
{"span_id": "t3", "parent_id": "m2", "kind": "tool", "name": "patch",
"start_ms": 6300, "end_ms": 6550}
]
}
Save the judge as exclusive_span.py and the fixture as run.json, then run it as a gate, not as a dashboard widget.
python3 exclusive_span.py run.json; echo exit:$?
On this fixture the wall is 8400 ms. The union of spans leaves a hole from 2700 to 4500, plus short edges at start and finish. Sibling tools t1 and t2 overlap by 350 ms, so adding their inclusive times invents 350 ms of serial work that never happened. Exclusive model time and exclusive tool time become the two columns you can actually budget. The script exits 2 because the untraced remainder is larger than a quarter of the run. That is the point.
A second command turns the same file into a regression check. Keep a known-good remainder ceiling next to the fixture. If a prompt change stretches the hole, the gate fails before anyone calls the agent “faster” because wall-clock happened to drop on a warm cache.
python3 - <<'PY'
import json, pathlib, subprocess, sys
raw = json.loads(pathlib.Path("run.json").read_text())
assert raw["ended_at_ms"] - raw["started_at_ms"] == 8400
proc = subprocess.run([sys.executable, "exclusive_span.py", "run.json"])
print("gate_status", proc.returncode)
PY
Use wall-clock when you care about user-visible wait. Use inclusive parent duration when you are debugging a single subtree and you want the doll, not the parts. Use exclusive duration when you allocate cost to a kind. Use the untraced remainder when you decide whether the tracer is complete enough to argue from. Mixing those four numbers is how teams convince themselves a chatty model is a fast toolchain.
The 25% remainder threshold in the script is a local policy, not a law. Tighten it on short, fully instrumented loops. Loosen it if your runtime injects GC pauses you do not span on purpose. Do not copy the constant into a vendor SLA. The useful part is the formula, not the cutoff.
Clock skew will lie. If tools run on another host and stamps are not on the same clock, overlap pairs become fiction and exclusive math subtracts the wrong children. Missing end_ms is worse: an open span makes inclusive duration undefined, so the script refuses the run rather than inventing a close. Async tools that finish after the parent has already closed will look like orphans; exclusive parent time will be too large and the remainder too small. A forest that is actually a DAG, with two parents claiming one child, is outside this model. Fix the shape first.
This debug loop is the wrong tool if you only have stdout lines, token counts, or a UI timer. It is also the wrong tool if your agent is a single model call with no tools; the second failure path will keep firing, and it should. Teams that need distributed tracing with baggage, sampling, and tail-based retention want an OpenTelemetry pipeline, not a hundred-line judge. The script exists to make a local run honest before you scale the lie.
Current public debate likes to separate “vibe” from engineering by tone. Duration attribution is blunter. A run whose exclusive tool time is zero did not touch the working tree in any spanned way. A run whose remainder is half the wall-clock did work you cannot replay. Neither case is fixed by a greener unit test that never saw the hole.
If you already emit closed spans from your own harness, the judge is enough. If you need a place to exercise the agent while you iterate on that harness, MonkeyCode’s free model access and free server option can host the loop so the remainder math stays local. Disclosure: This article was prepared as part of MonkeyCode's product outreach.
Ship the gate next to the fixture. When exclusive tool time rises and the untraced fraction falls, you have a trace you can budget. Until then, wall-clock is only how long you waited to be unsure.
Top comments (0)