DEV Community

Sam Sun
Sam Sun

Posted on

A Laptop Clock Cannot Order Remote Agent Spans

A laptop clock cannot order spans that were recorded on a remote agent host. Sort those records by trace_id and span_id, not by wall time. Treat every timestamp as an annotation from a clock domain you have not yet proven equal.

The failure mode is a false order. A local log line prints a tool payload at 12:00:01.410Z. The remote span for the same call records start_time=12:00:03.002Z. A time-sorted view now shows the result before the request. The model is not traveling backward. Two oscillators are.

This split is ordinary once generation and tools leave the debugger process. Free model access on a free server is enough to create it. The collector sits beside the agent. The engineer tails stdout on a laptop. Both sides stamp events with whatever that operating system currently believes is UTC.

Disclosure: This article was prepared as part of MonkeyCode's product outreach. MonkeyCode matters here only because its free model access and free server option place the generation hop on a host the laptop does not control. The join procedure below does not depend on that product. It depends on identifiers surviving the hop.

Time is not the graph

A trace is an identifier graph. Time is a measurement taken by a clock. Mixing them produces three artifacts that get filed as model bugs: negative durations, overlapping spans that were marked exclusive, and child spans that appear to start before their parents.

Call the remote host clock C_r and the laptop clock C_l. For any shared event e that both sides observe, skew is C_r(e) - C_l(e). If that quantity is not stable across the length of one run, duration math that subtracts a laptop stamp from a remote stamp is undefined. Concurrent tool calls make the damage visible because their true order is the call graph, not the arrival time of log lines on a USB-C cable.

The reusable rule is narrow. Join first on W3C traceparent fields. Compute skew only from events that carry both a local receipt time and a remote span timestamp. Refuse to rank spans by C_l until the measured skew is smaller than the smallest span you actually care about. That last clause is the one dashboards skip.

W3C traceparent is a 55-character contract, not a log flavor. Version 00, a 32-hex trace, a 16-hex parent span, and a 2-hex flag field. If a proxy truncates the header, or mints a fresh span per hop and forgets to copy the trace, the laptop and the server still have clocks. They no longer have a join key. Repair the propagator before arguing about latency.

A minimal shared schema

The records below are constructed. They are not sampled from a customer account and they are not a benchmark. They exist so a test can fail when someone sorts by time and calls the result causality.

# join_clocks.py — proposed join, not a measured production trace
from __future__ import annotations

from dataclasses import dataclass
from typing import Optional
import json
import re

TRACEPARENT_RE = re.compile(
    r"^[\t ]*([0-9a-f]{2})-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})[\t ]*$"
)

@dataclass(frozen=True)
class LocalEvent:
    event_id: str
    trace_id: str
    span_id: str
    name: str
    recv_unix_ms: int  # laptop clock, epoch ms
    payload: str

@dataclass(frozen=True)
class RemoteSpan:
    trace_id: str
    span_id: str
    parent_span_id: Optional[str]
    name: str
    start_unix_ms: int  # remote host clock
    end_unix_ms: int
    status: str

def parse_traceparent(value: str) -> tuple[str, str]:
    m = TRACEPARENT_RE.match(value)
    if not m:
        raise ValueError(f"unusable traceparent: {value!r}")
    version, trace_id, span_id, flags = m.groups()
    if version != "00":
        raise ValueError(f"unsupported traceparent version {version}")
    return trace_id, span_id

def join_by_span(events: list[LocalEvent], spans: list[RemoteSpan]) -> list[dict]:
    index = {(s.trace_id, s.span_id): s for s in spans}
    rows = []
    for ev in events:
        span = index.get((ev.trace_id, ev.span_id))
        rows.append({
            "event_id": ev.event_id,
            "name": ev.name,
            "trace_id": ev.trace_id,
            "span_id": ev.span_id,
            "has_span": span is not None,
            "local_recv_ms": ev.recv_unix_ms,
            "remote_start_ms": None if span is None else span.start_unix_ms,
            "remote_end_ms": None if span is None else span.end_unix_ms,
            "remote_status": None if span is None else span.status,
            "skew_recv_minus_start_ms": (
                None if span is None else ev.recv_unix_ms - span.start_unix_ms
            ),
        })
    return rows
Enter fullscreen mode Exit fullscreen mode

A time sort on local_recv_ms and a time sort on remote_start_ms will disagree as soon as skew exceeds the gap between two tool calls. The join above does not care. It keys the map with the only values both sides must copy: the 32-hex trace and the 16-hex span. Missing keys stay missing. They do not get “nearby in time” substitutes. Nearby in time is how a write from trace B gets blamed on trace A.

Export the remote side as spans, not as a screenshot. A JSONL dump with one closed span per line is enough. The laptop side is noisier. Stdout, stderr, and the HTTP client each have a clock. Stamp recv_unix_ms at the moment the process observes the line, and copy traceparent off the line if the runtime echoed it. If the runtime did not echo it, the local event is not in the graph. It is a diary entry.

Measure skew before ranking

Skew is not a single integer. It is a distribution over shared events. The procedure uses events the laptop can observe only after the remote span exists: a tool result that echoes span_id. Receipt-minus-start is not duration. Duration lives inside one clock. Receipt-minus-start is a travel-plus-skew number, and it is useful only as a sample in that distribution.

def skew_samples(rows: list[dict]) -> list[int]:
    out = []
    for row in rows:
        if row["remote_start_ms"] is None:
            continue
        out.append(row["local_recv_ms"] - row["remote_start_ms"])
    return out

def skew_report(samples: list[int]) -> dict:
    if not samples:
        return {"n": 0, "usable_for_order": False, "reason": "no shared events"}
    samples = sorted(samples)
    median = samples[len(samples) // 2]
    spread = samples[-1] - samples[0]
    return {
        "n": len(samples),
        "min_ms": samples[0],
        "median_ms": median,
        "max_ms": samples[-1],
        "spread_ms": spread,
        # Proposed threshold: if spread exceeds the smallest tool gap you debug, stop.
        "usable_for_order": spread < 50,
    }

def order_inversions(events: list[LocalEvent], spans: list[RemoteSpan]) -> list[dict]:
    """Flag pairs whose local order and remote order disagree."""
    joined = {(e.trace_id, e.span_id): e for e in events}
    named = [s for s in spans if (s.trace_id, s.span_id) in joined]
    inversions = []
    for i, a in enumerate(named):
        for b in named[i + 1:]:
            local_a = joined[(a.trace_id, a.span_id)].recv_unix_ms
            local_b = joined[(b.trace_id, b.span_id)].recv_unix_ms
            remote_cmp = (a.start_unix_ms > b.start_unix_ms) - (
                a.start_unix_ms < b.start_unix_ms
            )
            local_cmp = (local_a > local_b) - (local_a < local_b)
            if remote_cmp != 0 and local_cmp != 0 and remote_cmp != local_cmp:
                inversions.append({
                    "a": a.span_id,
                    "b": b.span_id,
                    "remote_order": "a_before_b" if remote_cmp < 0 else "b_before_a",
                    "local_order": "a_before_b" if local_cmp < 0 else "b_before_a",
                })
    return inversions
Enter fullscreen mode Exit fullscreen mode

Read usable_for_order as a gate, not as a quality score. A 40 ms spread can still invert two 15 ms tool calls. If the debug question is which file write happened first, the identifiers on those write spans are the evidence. The clocks are commentary. Commentary that disagrees with the graph is how a retry gets described as “the model wrote twice at once.”

Parent-child checks belong on identifiers too. If tool_a.parent_span_id is not the generation span, the graph is broken even when every timestamp looks sorted. A pretty waterfall is not a propagator test. The waterfall can be drawn from bad times. The parent pointer cannot.

A constructed run

Two tool spans, one parent generation span, and three local log lines. The numbers are illustrative. They are chosen so a time-sorted laptop log lies.

def constructed_run() -> None:
    trace = "a" * 32
    parent = "b" * 16
    tool_a = "c" * 16
    tool_b = "d" * 16

    spans = [
        RemoteSpan(trace, parent, None, "generation", 1_000_000, 1_000_800, "ok"),
        RemoteSpan(trace, tool_a, parent, "read_file", 1_000_120, 1_000_200, "ok"),
        RemoteSpan(trace, tool_b, parent, "write_file", 1_000_150, 1_000_260, "ok"),
    ]
    events = [
        LocalEvent("e1", trace, parent, "generation_end", 1_000_640, "done"),
        LocalEvent("e2", trace, tool_a, "read_file_result", 1_000_090, '{"ok":true}'),
        LocalEvent("e3", trace, tool_b, "write_file_result", 1_000_310, '{"ok":true}'),
    ]

    rows = join_by_span(events, spans)
    print(json.dumps({
        "join": rows,
        "skew": skew_report(skew_samples(rows)),
        "inversions": order_inversions(events, spans),
    }, indent=2))
Enter fullscreen mode Exit fullscreen mode

e2 arrives on the laptop 30 ms before the remote read_file start. A time-sorted local log therefore claims the result preceded the call. The join still attaches e2 to tool_a. The inversion list reports that local order and remote order disagree for tool_a versus parent. That object is the bug report. It is a clock report, not a prompt report.

The same constructed run shows why “exclusive time” across hosts is not exclusive. Generation on C_r overlaps the laptop’s receipt of write_file_result on C_l. Subtracting those stamps fabricates an untraced remainder that never happened. Keep exclusive-time math inside C_r. If the remote collector does not emit closed spans, you do not have exclusive time. You have an unfinished sentence.

A practical debug loop follows from that. Pull one failing trace_id from the remote export. Parse every local line that carries the same trace_id. Join. Print inversions and the skew spread. If inversions exist, stop talking about the model. If the spread is larger than the tool gap under study, stop talking about order. Only a clean join with a small spread is allowed to support a duration claim, and even then the duration must be computed from one side’s stamps.

# proposed local commands — not an executed session log
python join_clocks.py > join.json
python - <<'PY'
import json
d = json.load(open("join.json"))
print("inversions", len(d["inversions"]))
print("skew", d["skew"])
PY
Enter fullscreen mode Exit fullscreen mode

A small regression test

The test is a proposal. It encodes the invariant: join stability under a constant skew, and a hard fail when ranking by the laptop clock would silently reorder work.

# test_join_clocks.py — proposed, not executed in this article
from join_clocks import (
    LocalEvent, RemoteSpan, join_by_span, order_inversions,
    skew_report, skew_samples,
)

def test_join_survives_constant_skew():
    trace, span = "1" * 32, "2" * 16
    spans = [RemoteSpan(trace, span, None, "tool", 5000, 5100, "ok")]
    events = [LocalEvent("x", trace, span, "tool_result", 5480, "ok")]
    rows = join_by_span(events, spans)
    assert rows[0]["has_span"] is True
    assert rows[0]["skew_recv_minus_start_ms"] == 480

def test_time_sort_is_not_the_gate():
    trace = "1" * 32
    a, b = "a" * 16, "b" * 16
    spans = [
        RemoteSpan(trace, a, None, "tool_a", 100, 150, "ok"),
        RemoteSpan(trace, b, None, "tool_b", 120, 180, "ok"),
    ]
    events = [
        LocalEvent("e_b", trace, b, "b_result", 90, "ok"),  # laptop saw b first
        LocalEvent("e_a", trace, a, "a_result", 200, "ok"),
    ]
    inv = order_inversions(events, spans)
    assert inv, "clock disagreement must surface as inversion, not as a silent reorder"
    report = skew_report(skew_samples(join_by_span(events, spans)))
    assert report["usable_for_order"] is False or inv
Enter fullscreen mode Exit fullscreen mode

Run it with python -m pytest test_join_clocks.py -q after both files are on PYTHONPATH. The assertion is the point. A green test that sorts by recv_unix_ms and happens to match remote order on one lucky run is not coverage. Luck is how clock bugs survive until concurrent tools appear on a Tuesday.

What the join is allowed to answer

When a debug question is about identity — which tool, which file, which retry — answer from trace_id, span_id, and parent_span_id. When the question is about cost of time — queue wait versus generation versus tool — answer from a single clock domain. If the only timestamps on hand mix C_r and C_l, convert nothing. Export the remote spans as-is and ignore local wall time for ordering.

Question Evidence that can answer it Evidence that cannot
Did this tool run in this trace? matching trace_id + span_id log order on the laptop
Did write happen after read? parent/child or explicit link, same clock mixed-host timestamps
How long did generation take? end - start on the remote span local print times
Why is duration negative? clock domain mix, not a model defect prompt text

Negative duration is a clock symptom. Overlapping exclusive spans across hosts are the same symptom. Neither is a reason to change temperature, top-p, or the system prompt. Those knobs do not synchronize NTP.

Retry logic is the other place mixed clocks impersonate a model. A second tool span is a new span_id. It is not an in-place update of the first. If the laptop logs collapse both results onto one line because “the name was the same,” the join will look like a duplicate payload on one span. Keep the call id. Names are for humans. Identifiers are for order.

Limitations

The procedure assumes both sides copy traceparent without truncation. Some proxies keep trace_id and mint a new span_id per hop. That remains joinable, but the laptop event must record the span it actually received, not the span a comment in the SDK promised. Version bytes other than 00 should fail closed. A parser that strips unknown versions will invent joins.

It also assumes a shared event exists. A generation span with no echoed id in stdout cannot be skew-measured. You can still store the span. You cannot claim the local log is late or early. Silence is not latency.

NTP steps during a run invalidate the spread test. Monotonic clocks do not survive a host boundary. If a free server recycles the process between runs, do not reuse skew from the previous process. Measure per run. Then throw the number away. A saved skew from yesterday is a third clock, and it will lie with confidence.

Sampling is out of scope and still fatal. A parent span that survives when the child error span was dropped will look healthy on both clocks. The join cannot reconstruct a span that was never exported. Completeness is a collector problem. This script only reports holes as has_span: false.

This is the wrong tool when the agent and the debugger already share one process and one clock. It is also the wrong tool for token accounting, prompt quality, or filesystem diffs. Those questions need other traces. The join will not tell you whether a model is correct. It will tell you whether your ordering evidence is even in the same universe. Do not use the laptop clock to gate CI. A flaky order inversion will page the model, not the time daemon.

If that remote host is already a MonkeyCode free server in your loop, export one failing trace and run the join before editing the prompt. The identifiers are the check. The dashboard sort order is not.

Top comments (0)