Two Clocks, One Agent Trace

If a span record carries both a wall-clock timestamp and a monotonic one, assume they will disagree on the run you actually care about. A single NTP step of two seconds is enough to invert the completion order of two tool calls, and from that moment your timeline viewer is rendering fiction. You then debug the fiction.

This is not an exotic edge case. Wall clocks get stepped when a host corrects accumulated drift, when a VM resumes after suspend, and when two containers in the same pod end up in different clock namespaces. A monotonic clock keeps counting through all of it, at the cost of being meaningless across machines. Traces need both numbers, and a debug loop needs to say out loud which one it is currently trusting.

The failure is quiet, and it looks like an agent bug

An agent run is a tree: a turn span opens, tool spans nest underneath it, and the interesting part is the order in which the tools actually executed. Almost every trace viewer sorts that tree by a timestamp. Sort on wall-clock start time and the tree looks plausible most of the time, which is exactly why the bug survives review.

Inject a step and the same tree contradicts itself. A tool.http_fetch span reports a wall duration of 2.5 seconds while its own monotonic delta says 0.5 seconds, because the clock moved forward while the span was open. A sibling tool.repo_diff then appears to finish before the fetch that preceded it. The tempting conclusion is that the agent issued calls out of order; the correct conclusion is that one column of your trace is arithmetic on a quantity that is not monotonic.

The fix is not to throw away wall clock. Humans need it, log correlation needs it, and your incident timeline needs it. The fix is to derive ordering from structure and a monotonic source, and to use wall clock only for display once the trace has been audited.

A span record that can be audited

Keep the record boring and explicit. One span per JSONL line, with a parent link, a per-process sequence counter, and both clocks sampled at the same two points in the span's life.

{"span_id":"s1","parent_id":"s0","tool":"tool.http_fetch","seq":1,
 "wall_start_ns":1700000000100000000,"wall_end_ns":1700000002500000000,
 "mono_start_ns":8200000000,"mono_end_ns":8500000000}

The seq field is the underrated one. It is a plain integer counter incremented in the process that opens the span, so it stays correct through any clock event, any suspend, and any migration. It cannot order work across processes, and it is not a distributed clock. Inside one process it is the most trustworthy ordering signal you have, and it costs one integer per span.

The auditor

The script below is standard library only, reads JSONL, and emits a report plus a reconstructed order. It checks three things that can each be verified locally: monotonic duration must not be negative, wall-minus-monotonic drift per span must stay under a tolerance, and a child's wall window must not escape its parent's when the child's own drift is small.

# clock_audit.py - Python 3.10+, standard library only.
import json
import sys
from dataclasses import dataclass

TOLERANCE_NS = 50_000_000  # 50 ms; above this, treat drift as a clock step


@dataclass(frozen=True)
class Span:
    span_id: str
    parent_id: str | None
    tool: str
    seq: int
    wall_start_ns: int
    wall_end_ns: int
    mono_start_ns: int
    mono_end_ns: int


def read_spans(path):
    spans = []
    required = {"span_id", "tool", "seq", "wall_start_ns",
                "wall_end_ns", "mono_start_ns", "mono_end_ns"}
    with open(path, encoding="utf-8") as fh:
        for lineno, line in enumerate(fh, 1):
            line = line.strip()
            if not line:
                continue
            try:
                row = json.loads(line)
            except json.JSONDecodeError as exc:
                raise SystemExit(f"{path}:{lineno}: bad JSON: {exc}") from exc
            missing = required - row.keys()
            if missing:
                raise SystemExit(f"{path}:{lineno}: missing {sorted(missing)}")
            spans.append(Span(row["span_id"], row.get("parent_id"), row["tool"],
                              row["seq"], row["wall_start_ns"], row["wall_end_ns"],
                              row["mono_start_ns"], row["mono_end_ns"]))
    if not spans:
        raise SystemExit(f"{path}: no spans")
    return spans


def audit(spans):
    by_id = {s.span_id: s for s in spans}
    problems = []
    for s in spans:
        wall = s.wall_end_ns - s.wall_start_ns
        mono = s.mono_end_ns - s.mono_start_ns
        drift = wall - mono
        if mono < 0:
            problems.append({"kind": "mono_inverted", "span": s.span_id,
                             "detail": f"monotonic duration {mono} ns"})
        if abs(drift) > TOLERANCE_NS:
            problems.append({"kind": "clock_step", "span": s.span_id,
                             "detail": f"wall-mono drift {drift / 1e6:.1f} ms"})
        parent = by_id.get(s.parent_id) if s.parent_id else None
        if parent and abs(drift) <= TOLERANCE_NS:
            if s.wall_start_ns < parent.wall_start_ns or s.wall_end_ns > parent.wall_end_ns:
                problems.append({"kind": "parent_violation", "span": s.span_id,
                                 "parent": parent.span_id,
                                 "detail": "child window escapes parent"})
    return {"spans": len(spans), "problems": problems,
            "timeline_trusted": not problems}


def causal_order(spans):
    """Order by parent links, then by (per-process seq, mono_start)."""
    by_id = {s.span_id: s for s in spans}
    kids, roots = {}, []
    for s in spans:
        if s.parent_id and s.parent_id in by_id:
            kids.setdefault(s.parent_id, []).append(s)
        else:
            roots.append(s)

    key = lambda s: (s.seq, s.mono_start_ns)
    ordered = []

    def walk(node):
        ordered.append(node)
        for child in sorted(kids.get(node.span_id, []), key=key):
            walk(child)

    for root in sorted(roots, key=key):
        walk(root)
    return ordered


if __name__ == "__main__":
    spans = read_spans(sys.argv[1])
    report = audit(spans)
    report["order"] = [s.span_id for s in causal_order(spans)]
    json.dump(report, sys.stdout, indent=2)
    sys.stdout.write("\n")
    sys.exit(0 if report["timeline_trusted"] else 2)

The non-zero exit code matters more than the report. Wire the auditor into the same place that regenerates your trace fixtures, and an untrusted timeline fails a job instead of quietly appearing in a dashboard.

Reproduce the step without touching a real clock

Manipulating a live clock is possible, but it is the wrong first move: libfaketime works through LD_PRELOAD and the exact invocation depends on your distro's library path and time format, while date -s inside a container needs privileges most CI runners will not grant. Inject the step into a fixture instead. It is deterministic, it runs anywhere, and it pins the exact failure you are trying to catch.

# test_clock_audit.py - run with: pytest -q test_clock_audit.py
import json, pathlib, subprocess, sys

STEP_NS = 2_000_000_000  # one 2 s NTP step


def write_fixture(tmp: pathlib.Path) -> pathlib.Path:
    w, m = 1_700_000_000_000_000_000, 8_000_000_000
    spans = [
        dict(span_id="s0", parent_id=None, tool="agent.turn", seq=0,
             wall_start_ns=w, wall_end_ns=w + 900_000_000,
             mono_start_ns=m, mono_end_ns=m + 900_000_000),
        # the clock moves forward while this span is open
        dict(span_id="s1", parent_id="s0", tool="tool.http_fetch", seq=1,
             wall_start_ns=w + 100_000_000, wall_end_ns=w + 500_000_000 + STEP_NS,
             mono_start_ns=m + 100_000_000, mono_end_ns=m + 500_000_000),
        dict(span_id="s2", parent_id="s0", tool="tool.repo_diff", seq=2,
             wall_start_ns=w + 600_000_000, wall_end_ns=w + 800_000_000,
             mono_start_ns=m + 600_000_000, mono_end_ns=m + 800_000_000),
    ]
    path = tmp / "trace.jsonl"
    path.write_text("\n".join(json.dumps(s) for s in spans) + "\n", encoding="utf-8")
    return path


def test_step_is_reported_and_order_survives(tmp_path):
    trace = write_fixture(tmp_path)
    out = subprocess.run([sys.executable, "clock_audit.py", str(trace)],
                         capture_output=True, text=True)
    report = json.loads(out.stdout)
    assert report["timeline_trusted"] is False
    assert out.returncode == 2
    assert "clock_step" in {p["kind"] for p in report["problems"]}
    assert report["order"] == ["s0", "s1", "s2"]

The fixture encodes both halves of the lesson. Sorting by wall end time puts s2 before s1, because s1 absorbed the step; the structural order built from parent_id and seq keeps the true sequence. Run the auditor directly and the report says so:

$ python clock_audit.py trace.jsonl
{
  "spans": 3,
  "problems": [
    {
      "kind": "clock_step",
      "span": "s1",
      "detail": "wall-mono drift 2000.0 ms"
    }
  ],
  "timeline_trusted": false,
  "order": ["s0", "s1", "s2"]
}
$ echo $?
2

Read the report as triage, not as a verdict

Symptom	Likely cause	Cheap check	Action
Wall duration far exceeds monotonic duration	NTP step, VM suspend, or clock namespace swap	per-span drift	Trust monotonic; mark the wall column suspect in that window
Child window escapes parent while drift is small	Async callback recorded under the wrong parent	seq gaps between siblings	Fix span parenting, not the timestamps
Monotonic duration is negative	Process re-exec, or two clock domains merged into one file	process or PID tag on the span	Split the trace per clock domain before ordering
Clocks agree and order is still wrong	Genuine concurrency with no causal link	concurrent siblings with equal parents	Add a span link or an explicit causal edge

That last row is the honest boundary of this method. Two parallel tool calls with no parent-child relationship are simply concurrent, and a flat sort will always impose an order that the system never had.

Where a free tier actually fits

Generating skewed traces by hand gets old after about the fourth variant, and the useful corpus is the boring one: hundreds of malformed traces covering steps at different points inside a span. I used MonkeyCode's free model access to generate those variants and its free server option to run the auditor and the fixture suite off my own machine, so the job did not depend on a laptop staying awake. As of this writing the operator advertises a 10M-token allowance on the free tier plus the free server option; allowances and hardware change, so check the current pricing page before you plan around either number.

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

Nothing in the auditor depends on that tier. The script, the fixture, and the pytest file above run on any Python 3.10+ interpreter, and if you already have a trace source you trust, you can point the auditor at a sample today and see whether the timeline you have been reading is the one that happened.

Limits, and who should skip this

This auditor assumes roughly one process per trace file and a sequence counter that is consistent within it. Cross-host tool calls need vector clocks or an explicit causal edge, not a per-process integer, and pretending otherwise will produce confident nonsense. It also flags suspects; it does not restore correctness. If you need billing-grade timing, NTP monitoring and synchronized hosts are the real fix, and this script is at best the alarm that tells you to go look.

Skip the whole approach if your SDK already emits monotonic timestamps with stable parent links and you trust the collector that assembles them. Adding a second auditor to a pipeline that is already correct is duplicate work, and a second source of ordering truth is worse than one. Skip it too if you cannot change span emission at all: this tool can tell you a wall window is unreliable, but it cannot recover an order that was never recorded.