Arrival order is evidence. Timestamps are a rumor.
That is the whole argument, and it deserves one concrete failure before any code. An agent writes a tool call at t=12.104, the sandbox writes the result at t=12.103 because two hosts disagree about the wall clock, and your viewer sorts by ts. The result now renders above the call it answers. Twenty minutes later you are hunting a tool that "returned before it ran," and the trace was never wrong — your sort was.
The second failure is quieter. JSONL appenders flush when they feel like it, so under load file order and happened order diverge by a few lines. Sub-millisecond collisions make the sort unstable, so the same run can render into two different shapes on two machines. Debug loops die on that nondeterminism, not on bugs.
The fix is not a better clock. Demote ts to advisory metadata, promote parent links and arrival order to ground truth, and add a pass that reports exactly how much your trace disagrees with itself.
A trace that survives reordering
Three fields do the work: span_id, parent_span_id, event. The fourth is the line number, and it is free — you never write it down, you just stop destroying it.
{"event":"span_start","span_id":"s1","parent_span_id":null,"ts":1762700412.101}
{"event":"tool_call","span_id":"s1.t1","parent_span_id":"s1","ts":1762700412.104,"tool":"write_file"}
{"event":"tool_result","span_id":"s1.t1","parent_span_id":"s1","ts":1762700412.103,"ok":true}
{"event":"span_end","span_id":"s1.t1","parent_span_id":"s1","ts":1762700412.106}
Read lines two and three again: the result carries an earlier timestamp than the call. Nothing in the format is broken. Sort that file by ts and you have manufactured a mystery out of four valid rows.
The ordering pass
What follows is a complete auditor. It reads JSONL, counts how often file order and timestamp order disagree, rebuilds the span tree from parent links, and flags the two structural states that make a trace untrustworthy: a span whose parent was never observed, and a tool call that never got a result.
#!/usr/bin/env python3
"""trace_order.py — audit timestamp ordering; emit a canonical arrival view.
python trace_order.py runs/today.jsonl --out report.json --canonical ordered.jsonl
"""
import argparse, json, sys
REQUIRED = ("span_id", "event")
def load(path):
bad, events = [], []
with open(path, encoding="utf-8") as fh:
for lineno, raw in enumerate(fh, 1):
raw = raw.strip()
if not raw:
continue
try:
ev = json.loads(raw)
except json.JSONDecodeError as exc:
bad.append({"line": lineno, "error": str(exc)})
continue
missing = [k for k in REQUIRED if k not in ev]
if missing:
bad.append({"line": lineno, "missing": missing})
continue
ev["_arrival"] = len(events)
events.append(ev)
return events, bad
def inversions(events):
"""Pairs (i, j), i < j in arrival order, where ts[i] > ts[j]."""
ts = [ev.get("ts") for ev in events]
if any(t is None for t in ts):
return None
if len(ts) > 20000:
return "skipped (>20k events)"
return sum(1 for i in range(len(ts)) for j in range(i + 1, len(ts)) if ts[i] > ts[j])
def structure(events):
first, parent, closed = {}, {}, {}
for ev in events:
sid = ev["span_id"]
first.setdefault(sid, ev["_arrival"])
parent.setdefault(sid, ev.get("parent_span_id"))
if ev["event"] == "span_start":
closed.setdefault(sid, False)
elif ev["event"] == "span_end":
closed[sid] = True
orphans = sorted(s for s in first if parent.get(s) and parent[s] not in first)
unclosed = sorted(s for s, done in closed.items() if not done)
return first, parent, orphans, unclosed
def dangling(events):
open_calls, out = {}, []
for ev in events:
if ev["event"] == "tool_call":
open_calls.setdefault(ev["span_id"], ev["_arrival"])
elif ev["event"] == "tool_result":
open_calls.pop(ev["span_id"], None)
for sid, at in sorted(open_calls.items(), key=lambda kv: kv[1]):
out.append({"span_id": sid, "arrival": at})
return out
def root_of(sid, parent, first):
seen = set()
while parent.get(sid) in first and parent[sid] != sid and sid not in seen:
seen.add(sid)
sid = parent[sid]
return sid
def annotate(events, first, parent):
for ev in events:
sid = ev["span_id"]
depth, cursor = 0, sid
while parent.get(cursor) in first and parent[cursor] != cursor:
cursor = parent[cursor]
depth += 1
ev["_root"] = first[root_of(sid, parent, first)]
ev["_depth"] = depth
ev["_first"] = first[sid]
return events
def main():
ap = argparse.ArgumentParser()
ap.add_argument("trace")
ap.add_argument("--out", default="-")
ap.add_argument("--canonical")
args = ap.parse_args()
events, bad = load(args.trace)
first, parent, orphans, unclosed = structure(events)
inv = inversions(events)
pairs = len(events) * (len(events) - 1) // 2
report = {
"events": len(events),
"bad_lines": bad,
"inversions": inv,
"inversion_ratio": None if not isinstance(inv, int) or not pairs else round(inv / pairs, 4),
"orphan_spans": orphans,
"unclosed_spans": unclosed,
"dangling_tool_calls": dangling(events),
}
text = json.dumps(report, indent=2, sort_keys=True)
if args.out == "-":
print(text)
else:
with open(args.out, "w", encoding="utf-8") as fh:
fh.write(text + "\n")
if args.canonical:
annotate(events, first, parent)
events.sort(key=lambda e: (e["_root"], e["_depth"], e["_first"], e["_arrival"]))
with open(args.canonical, "w", encoding="utf-8") as fh:
for ev in events:
fh.write(json.dumps({k: v for k, v in ev.items() if not k.startswith("_")}, sort_keys=True) + "\n")
sys.exit(1 if orphans or unclosed or report["dangling_tool_calls"] else 0)
if __name__ == "__main__":
main()
The non-zero exit is the point. It turns the auditor into a gate instead of a dashboard:
python trace_order.py runs/today.jsonl --out report.json --canonical ordered.jsonl \
|| echo "trace unsound: do not diff content yet"
Reading the report
inversions is the honest number: ordered pairs in the file that the timestamps claim happened the other way around. Zero means ts and arrival agree on your system, and sorting by ts is harmless — keep doing it. Anything above a small convention threshold you pick yourself, say inversion_ratio > 0.01, means ts is not a sort key for you, full stop.
The shape of the inversions is a clock hint. Inversions clustered inside one span usually mean one host's clock is off; inversions spread thinly across many spans usually mean buffered writes reordered lines on flush. Both are infrastructure facts, and neither is fixed by editing the agent.
orphan_spans is the truncation alarm. A child span whose parent never appears means the trace was sampled, rotated mid-run, or written by two processes into two files. Every conclusion you draw about that parent's decision is now unsupported, so stop drawing it.
dangling_tool_calls is the attribution alarm. The call exists, the result does not: the tool crashed, the run was killed, or the result landed in a different sink. In all three cases the file diff that follows belongs to nobody, and any "the agent broke it" story is unfalsifiable.
Harvesting enough runs to see skew
Skew is a distribution, not a property of one run. A single trace can look perfectly ordered by luck; the ratio only becomes actionable across a batch. That is a volume problem, and volume is where cheap inference stops being a luxury: the auditor does not care how strong the model was, only that many short runs each produced a JSONL file.
Free model access is the cheapest way to get that batch, and a free server option removes the provisioning step entirely. MonkeyCode is an open-source project that offers both; the free-tier terms, limits, and availability are the project's to define and they change, so read them on the project's page rather than trusting any post about them, this one included.
Disclosure: This article was prepared as part of MonkeyCode's product outreach.
The fit is narrow and worth stating plainly. This workflow needs dozens of small, disposable runs and a file you can read; it does not need a flagship model, a long context, or a benchmark win. If you already have budgeted inference elsewhere, use that — the script is indifferent to the provider.
The loop
Capture first, and capture boringly: one append-only JSONL per run, never rewritten, never deduplicated. Audit immediately after the run while the machine state is still fresh, and keep report.json next to the trace so the evidence and its health check travel together.
Aggregate before you interpret. Because span ids differ run to run, diffing traces across runs is mostly noise; diffing the shape is not. One jq fold over the reports gives you the batch view:
jq -s '[.[] | {events, ratio: .inversion_ratio,
orphans: (.orphan_spans | length),
dangling: (.dangling_tool_calls | length)}]' runs/*.report.json
If orphans appear at all, fix the sink before you touch the agent — split writers, rotation, and sampling are capture bugs, and they will keep manufacturing fake mysteries. Only once the trace is structurally sound do you read the canonical file top to bottom and start arguing about behavior. The gate is not there to slow you down; it is there so that the argument you are about to have is about software.
Where this breaks
If your agent is one process, one clock, and fully synchronous, and you never compare traces against each other, this pass is ceremony. Skip it and spend the time on tests.
The inversion counter is O(n²) and refuses to run past twenty thousand events, which is a deliberate limit rather than an achievement; for larger traces sample the middle of the run or swap in a Fenwick tree. Parent links containing cycles will make the depth walk spin, so cap the walk if your runtime can emit self-parented spans. And if you already emit OpenTelemetry spans into a collector that preserves order, you have better plumbing than this — keep it, and use the ratio as a health check rather than a rewrite.
Finally, be clear about what the report does not say. It says nothing about whether the agent's behavior was correct, efficient, or safe. It says whether the evidence is readable, which is the cheaper question and the one you must answer first.
Sort by ts and you get a story. Sort by arrival and parent links and you get what happened. Only one of those is debuggable.
Top comments (0)