Your Trace Shows the Wrong Order. Measure Clock Skew Before You Debug

Two in the morning, one failing agent run, and a trace that made no sense.

The tool result sat four milliseconds before the tool call that produced it. I read the retry logic for three hours. The retry logic was fine.

The trace was wrong. Two machines wrote it. Their clocks disagreed by about 250 ms.

The bug is in the timeline, not the agent

A single trace often has more than one clock behind it. The agent process stamps spans on its own host. A sandbox or tool server stamps results on another machine.

When those clocks drift, ordering breaks. You then debug a sequence that never happened.

Watch for these symptoms:

• A child span ends before its parent starts.
• A tool result carries an earlier timestamp than its request.
• Server-side durations come out negative.
• Skew grows steadily across a long run.
• One host's spans all look suspiciously fast.

Any one of these can be a real bug. All of them together usually mean one thing. Your timestamps came from different clocks.

Why two clocks drift apart

The usual causes are boring and common:

• Date.now(), time.time(), and friends read a wall clock, not a monotonic one.
• Containers share the host clock, but VMs can suspend and resume.
• NTP corrections can step a clock forward or backward.
• Small rate differences accumulate over hours.

Nothing here is exotic. It is the default in many agent deployments. Measure the offset before you blame the agent.

Do not fix it by re-sorting the trace

Sorting by timestamp hides the problem. The wrong order becomes a consistent wrong order. You lose the signal that told you something was off.

Fix the clocks first. Sort second.

Estimate the offset from paired spans

Every tool call gives you four timestamps:

• t1 client sends the request
• t2 server receives it
• t3 server sends the result
• t4 client receives the result

Two numbers fall out of those four.

offset = ((t2 - t1) + (t3 - t4)) / 2
rtt    = (t4 - t1) - (t3 - t2)

This is the classic four-timestamp exchange used by NTP-style sync. It assumes network delay is roughly symmetric. Filter for low-RTT pairs and take the median.

Set max_rtt_ms from your own p50 RTT, not from a blog post. A pair above that threshold tells you about queuing, not about clocks. More pairs help. Aim for dozens, not three.

The estimator

#!/usr/bin/env python3
import json, statistics

def load(path):
    with open(path) as fh:
        for line in fh:
            line = line.strip()
            if line:
                yield json.loads(line)

def quads(spans):
    by_id = {s['span_id']: s for s in spans}
    for s in spans:
        if s.get('kind') != 'tool_call':
            continue
        r = by_id.get(s.get('result_span_id'))
        if r is None:
            continue
        yield s['ts_ms'], r['ts_ms'], r['end_ms'], s['end_ms']

def split(t1, t2, t3, t4):
    offset = ((t2 - t1) + (t3 - t4)) / 2.0
    rtt = (t4 - t1) - (t3 - t2)
    return offset, rtt

def estimate(qs, max_rtt_ms=50.0, min_pairs=5):
    kept = []
    for t1, t2, t3, t4 in qs:
        off, rtt = split(t1, t2, t3, t4)
        if rtt <= max_rtt_ms:
            kept.append(off)
    if len(kept) < min_pairs:
        raise SystemExit('need %d low-RTT pairs, kept %d' % (min_pairs, len(kept)))
    return statistics.median(kept), len(kept)

if __name__ == '__main__':
    import sys
    spans = list(load(sys.argv[1]))
    off, n = estimate(quads(spans))
    print('offset_ms=%.1f pairs=%d' % (off, n))

A fixture test with a known offset

Never trust an estimator you have not tested against a known answer. Inject an offset, then check recovery.

import random
from spanskew import estimate

def test_recovers_known_offset():
    random.seed(7)
    injected = 250.0
    base = 1_700_000_000_000
    qs = []
    for i in range(40):
        send = base + i * 1000
        up = random.uniform(4, 6)
        down = random.uniform(4, 6)
        work = 5.0
        t2 = send + up + injected
        t3 = t2 + work
        t4 = t3 - injected + down
        qs.append((send, t2, t3, t4))
    off, n = estimate(qs, max_rtt_ms=30.0)
    assert n == 40
    assert abs(off - injected) <= 2.0

The fixture injects a 250 ms offset. The estimator must recover it within 2 ms. If it cannot, your RTT filter or your median is wrong.

Eyeball the raw trace first

One cheap check before any math:

jq -r 'select(.kind=="tool_call") | [.span_id, (.end_ms - .ts_ms)] | @tsv' trace.jsonl | sort -k2 -n | head

Negative or near-zero durations on tool calls are a strong skew hint. So is a result span that sorts before its request span.

A minimal trace line pair looks like this:

{"span_id":"s1","kind":"tool_call","ts_ms":1700000000000,"end_ms":1700000000042,"result_span_id":"s1r"}
{"span_id":"s1r","kind":"tool_result","ts_ms":1700000000250,"end_ms":1700000000255}

Correct the trace, then re-read it

Work in this order:

1. Group spans by emitting host.
2. Pick one host as the reference clock.
3. Compute the median offset for every other host.
4. Shift those hosts' timestamps by their offset.
5. Rebuild parent and child links from span ids, not timestamps.
6. Re-run the original query on corrected stamps.

Step five matters most. Span ids are stable facts. Timestamps are measurements.

Which evidence to trust

Evidence	Trust it when	Fallback
Wall-clock timestamps	Hosts are synced and RTT is low	Corrected offset
Span nesting	Parent ids exist and are unique	Rebuild from ids
Duration fields	Emitted by the same host	Recompute from stamps
Log line order	A single writer, single file	Add sequence numbers

Where to run this harness

The harness is small and CPU-only. It reads JSONL and prints one number. I run it on MonkeyCode's free server option and use free model access to draft the span rules before they land in CI.

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

A stable box matters here. Skew work depends on running the same fixture many times. If you want to try the harness without provisioning a machine, the free server option is a reasonable place to start.

Limits, and who should skip this

• The symmetry assumption breaks badly under heavy upload or download.
• One offset per run fails if NTP steps the clock mid-run.
• Fewer than five low-RTT pairs means you have no estimate. Do not guess.
• Single-host traces do not need any of this.
• If your collector already normalizes clocks, use that instead.
• Monotonic clocks fix ordering within one host. They do not fix cross-host comparison.
• This tells you nothing about which component is slow. It only fixes the axis.

Skip it entirely if every span comes from one process with one monotonic clock. You have no problem to solve.

A reusable debug loop

1. Reproduce the run and keep the JSONL trace.
2. Count the emitters. If there is only one, stop here.
3. Run the jq check for negative or tiny durations.
4. Estimate offsets and keep only low-RTT pairs.
5. Correct stamps, then rebuild links from span ids.
6. Re-run the failing query on corrected data.

Most of that loop is one script and one jq call. Step one is the step people skip.

A trace is a measurement, not a recording. Measure the ruler before you measure the bug.