Riley Wang

Posted on Sep 8

Agent Traces Hide Wait Time. Split Three Lanes.

#ai #agents #debugging #observability

A checkout agent froze during a Tuesday traffic spike.
Logs showed a green span for every tool.
The customer still waited a full forty-one seconds.

Token usage charts looked healthy for the whole run.
Ops blamed the language model first, as usual.
The production prompt had not changed since Friday.

Recorded tool HTTP codes were all two hundred.
Nothing on the on-call dashboard looked broken.
The missing signal was idle time, not tokens.

The run waited on a lock, then on DNS.
Those waits never became billed model tokens at all.
A single LLM latency number hid both waits.

One latency number hides the stall

Most agent dashboards still plot only one duration.
They name it model time or request latency.
That single number mixes generation, I/O, and sleep.

A two-second generate can sit behind a thirty-second lock.
The chart still colors the span as model work.
Prompt edits then waste the next two days.

Split wall-clock time before you touch any prompts.
If idle plus tool exceed model time, stop.
Do not buy tokens to fix a mutex wait.

Request sampling breaks causal agent runs

Classic APM samples one percent of HTTP spans.
That old heuristic fits stateless web handlers only.
An agent run is a short causal chain.

Drop two spans and the whole plot collapses.
Retry three is meaningless without retry two nearby.
A child span without its parent is noise.

Keep the whole run or keep nothing useful.
Per-span sampling also biases those slow multi-tool paths.
Longer agent runs with more tools become under-represented.

Fast crashes vanish from the retained sample set.
Your heatmap then lies about real users.
Close the run first, then sample only after that.

Three lanes, not one clock

Give every closed interval exactly one named lane.

Model lane

Count queue time, token generation, and stream parse.
Count only work gated on the model API.
Do not park tool HTTP inside this lane.

Tool lane

Cover DNS, connect, execute, and result serialize steps.
Record your own status, not only HTTP codes.
A two-hundred response can still be wrong.

Idle lane

Cover locks, backoff, rate-limit sleeps, and human gates.
This lane is where "slow model" stories die.
If idle wins, you have an orchestration bug.

Sum the three lanes against wall clock.
Mismatch means overlapping spans or bad clocks exist.
Treat mismatch as a tracer bug, not noise.

A small JSONL contract

Label this format as a local proposal.
It is not an industry standard.

{"run_id":"r-9f2","seq":1,"lane":"model","name":"plan","t_start_ms":0,"t_end_ms":812,"status":"ok"}
{"run_id":"r-9f2","seq":2,"lane":"idle","name":"lock_wait","t_start_ms":812,"t_end_ms":24010,"status":"ok"}
{"run_id":"r-9f2","seq":3,"lane":"tool","name":"inventory.get","t_start_ms":24010,"t_end_ms":40702,"status":"ok","http":200}
{"run_id":"r-9f2","seq":4,"lane":"idle","name":"stop","t_start_ms":40702,"t_end_ms":40702,"status":"ok"}

Required fields stay intentionally small.

run_id binds events to one user task
seq restores order when files shuffle
lane must be model, tool, or idle
t_start_ms and t_end_ms are run-relative
status is ok, error, or timeout

HTTP success is not your status field.
Set status from a checker you own.
Garbage payloads should mark the span error.

Emit lanes from the agent loop

The helper below is a runnable local example.
It uses monotonic time inside one process.
Do not mix wall clocks from two hosts.

# example emitter — not a production tracer
from __future__ import annotations

import json
import time
from contextlib import contextmanager
from pathlib import Path
from typing import Iterator


class RunTrace:
    def __init__(self, run_id: str, path: str) -> None:
        self.run_id = run_id
        self.path = Path(path)
        self.seq = 0
        self.origin = time.monotonic()

    def _now_ms(self) -> int:
        return int((time.monotonic() - self.origin) * 1000)

    @contextmanager
    def lane(self, lane: str, name: str, **extra: object) -> Iterator[None]:
        if lane not in {"model", "tool", "idle"}:
            raise ValueError(f"bad lane {lane}")
        start = self._now_ms()
        status = "ok"
        try:
            yield
        except Exception:
            status = "error"
            raise
        finally:
            self.seq += 1
            event = {
                "run_id": self.run_id,
                "seq": self.seq,
                "lane": lane,
                "name": name,
                "t_start_ms": start,
                "t_end_ms": self._now_ms(),
                "status": status,
            }
            event.update(extra)
            with self.path.open("a", encoding="utf-8") as handle:
                handle.write(json.dumps(event) + "\n")


# labeled example loop, not a live customer bot
def fake_checkout(trace: RunTrace) -> None:
    with trace.lane("model", "plan"):
        time.sleep(0.05)
    with trace.lane("idle", "lock_wait"):
        time.sleep(0.20)
    with trace.lane("tool", "inventory.get", http=200):
        time.sleep(0.12)
    with trace.lane("idle", "stop"):
        pass

Wrap each phase with a lane context.
Model calls go in model.
Inventory I/O goes in tool.

time.sleep for backoff goes in idle.
Flush one JSON object per closed interval.
Never sample while seq is still growing.

Sampling mid-run is how plots go hollow.
Write the stop interval before any copy job.
A file without stop stays in quarantine.

Completeness before retention

A run is complete only when all hold.

Sequence numbers are contiguous from one
Every interval has t_end_ms >= t_start_ms
Lane sums match wall clock within 50ms
The last event is named stop

If any check fails, quarantine the file.
Incomplete traces teach the wrong story.
They are worse than an empty folder.

Fifty milliseconds is a local tolerance.
Laptop NTP drift will trip a tighter bound.
Prefer monotonic clocks for t_start_ms.

Print a waterfall from a closed file

Run the checker against one run_id.
It should refuse gaps and clock skew.

#!/usr/bin/env python3
"""Lane waterfall for one closed agent run."""
from __future__ import annotations

import json
import sys
from collections import defaultdict
from pathlib import Path

LANES = ("model", "tool", "idle")
TOLERANCE_MS = 50


def load_events(path: Path, run_id: str) -> list[dict]:
    rows = []
    with path.open(encoding="utf-8") as handle:
        for line in handle:
            line = line.strip()
            if not line:
                continue
            event = json.loads(line)
            if event.get("run_id") == run_id:
                rows.append(event)
    rows.sort(key=lambda event: int(event["seq"]))
    return rows


def assert_complete(events: list[dict]) -> None:
    if not events:
        raise SystemExit("no events for run")
    seqs = [int(event["seq"]) for event in events]
    expected = list(range(1, len(seqs) + 1))
    if seqs != expected:
        raise SystemExit(f"gap in seq: {seqs}")
    if events[-1].get("name") != "stop":
        raise SystemExit("run never closed")


def lane_ms(events: list[dict]) -> dict[str, int]:
    totals: dict[str, int] = defaultdict(int)
    for event in events:
        lane = event["lane"]
        if lane not in LANES:
            raise SystemExit(f"bad lane {lane}")
        width = int(event["t_end_ms"]) - int(event["t_start_ms"])
        if width < 0:
            raise SystemExit(f"negative width at seq {event['seq']}")
        totals[lane] += width
    return dict(totals)


def bar(ms: int, scale: float) -> str:
    if scale <= 0:
        return ""
    return "#" * int(round(ms / scale))


def main() -> None:
    if len(sys.argv) != 3:
        raise SystemExit("usage: waterfall.py TRACE.jsonl RUN_ID")
    events = load_events(Path(sys.argv[1]), sys.argv[2])
    assert_complete(events)
    totals = lane_ms(events)
    wall = int(events[-1]["t_end_ms"]) - int(events[0]["t_start_ms"])
    summed = sum(totals.get(lane, 0) for lane in LANES)
    if abs(summed - wall) > TOLERANCE_MS:
        raise SystemExit(f"clock mismatch wall={wall} sum={summed}")
    peak = max(totals.values()) if totals else 1
    scale = peak / 40
    print(f"run {sys.argv[2]} wall_ms={wall}")
    for lane in LANES:
        ms = totals.get(lane, 0)
        pct = 0 if wall == 0 else 100 * ms / wall
        print(f"{lane:5} {ms:8}ms {pct:5.1f}% {bar(ms, scale)}")
    dominant = max(LANES, key=lambda lane: totals.get(lane, 0))
    print(f"dominant_lane={dominant}")
    if dominant != "model":
        print("action: do not tune the prompt first")


if __name__ == "__main__":
    main()

python3 waterfall.py checkout.jsonl r-9f2

Fixture output for the Tuesday stall:

run r-9f2 wall_ms=40702
model     812ms   2.0% #
idle    23198ms  57.0% #######################
tool    16692ms  41.0% ################
dominant_lane=idle
action: do not tune the prompt first

Those digits are a fixture, not a benchmark.
Replace them with your closed traces.
The lesson is lane dominance, not the ms.

If idle dominates, stop prompt tuning.
If tool dominates, inspect timeouts next.
If model dominates, then inspect tokens.

Reproducible test plan

Treat this as a checklist, not a paper.

Build three fixtures: model, tool, idle heavy
Assert the script names the dominant lane
Delete one seq value and expect a nonzero exit
Keep HTTP 200 while status becomes error
Shift t_end_ms by 500ms and expect mismatch
Confirm incomplete files stay quarantined

If step three still prints bars, halt.
The completeness gate is not real yet.
Fix the gate before any dashboard work.

Step four is easy to skip under pressure.
Green HTTP will fool a tired on-call engineer.
Keep status independent from the transport code.

Retention decision table

Do not copy web APM retention defaults.
Agent files carry tool arguments and PII.
Shorter retention is safer than a leak.

Redact on the origin host

API keys appear in tool arguments often.
User emails appear in search queries often.
A debug copy can become a second incident.

Strip secrets before the file moves.
Keep hashes of payloads if you need diffs.
If you cannot redact, do not ship the file.

A free server as a quiet checker

Closed JSONL files are small on purpose.
Overnight jobs do not need a GPU.
A free server is enough for the checker.

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

MonkeyCode provides free model access and a free server option.
Park the waterfall job on that free server.
Use free model access to synthesize fixtures only.

Do not send production user runs to a free tier.
Redact first, or keep traces on the origin host.
The habit matters more than the vendor.

Practical loop, if you need a default.

Agents append JSONL on local disk
Cron copies only closed, redacted runs
waterfall.py fails incomplete files
Mail a dominant-lane summary each morning
Open idle-heavy and error runs first

If you try that free server, start with fixtures.

Limitations

This schema ignores nested child agents.
It also ignores concurrent tool calls.
Overlapping intervals will exceed wall clock.

Serialize tools or record a true span graph.
The fifty millisecond bound is arbitrary.
Mislabeling sleep as tool recreates the lie.

The script does not prove answer quality.
A fast wrong answer still looks model-heavy.
Add semantic checks in a later pass.

Who should skip this

Skip it for single-shot completions with no tools.
Skip it if legal blocks storing tool arguments.
Skip it if you already have trusted causal tracing.

Skip the copy step when redaction is incomplete.
Local disks beat leaked traces every time.
This workflow is for short tool loops you own.

On the next freeze

Ask for the closed JSONL, not a screenshot.
Ask which lane ate the wall clock.
If idle wins, fix orchestration first.

If tool wins, inspect timeouts and payloads.
If model wins, then look at tokens.
Keep whole runs until that story is boring.

DEV Community