Skip to content

10 min read

Per-step traces are a logging feature, not a topology

On this page

With the chunked loop matching the pipeline on obligation F1 to within a point, the meeting that followed had a different shape than anyone expected. Nobody defended the three-agent design on accuracy. What the two engineers who had been on call for the contract-review service defended was the trace view: every agent emits its own span — the tracing world's name for one timed record of one unit of work, which is what a trace is assembled from — with its own input, output, token counts and duration, and since the migration the median time to diagnose a production defect has gone from about four and a half hours to about forty minutes. Their position was that they were not going back to grepping a five-turn transcript, and that this was worth more than the money.

The forty minutes is real, it is measured, and it is not what the 3x is buying. Everything in that trace view is a property of what got logged, and none of it is a property of the work running in three processes.

What actually produced the debugging gain

Take the trace view apart into the things an on-call engineer uses. There are five: a named unit of work with a start and end time; the exact input that unit received; the exact output it produced; its token and cost attribution; and the ability to replay it in isolation against a saved input. When a review comes out with a missing indemnity obligation, the engineer opens the trace, sees that extract ran 18 seconds on 31,400 input tokens and returned 62 obligations, pulls its saved input, replays it locally, and either reproduces the miss or learns that the input was already wrong.

Every one of those five is a logging artifact. The reason the pipeline has them and the old loop did not is that a process boundary made them unavoidable: the orchestrator had to serialise something to hand to the next agent, and once you are serialising it anyway, persisting it costs one line. The loop had no such moment. Its five turns lived inside a single messages array, its logging emitted one span per HTTP request with a token count and no content, and the transcript went to a debug log that rotated after 48 hours.

That is the whole mechanism. The pipeline did not make the system more observable; it made observability the path of least resistance, and the loop's observability was the path of most.

The same trace from one conversation

The chunked loop runs five named phases — plan, classify, extract, check, draft — and instrumenting them means emitting, per phase, a record with the schema from chapter 3. The loop already has an internal notion of which phase it is in, because its prompt switches on it.

python
import time, json, uuid
from contextlib import contextmanager

@contextmanager
def phase(run_id: str, name: str, seq: int, rendered_input: str, parent: str | None):
    """Emit a handoff-shaped span for one loop phase. Same schema as the
    pipeline's per-agent records, so the trace UI needs no changes."""
    span_id = f"ph-{seq}"
    t0 = time.monotonic_ns()
    box: dict = {}
    try:
        yield box                                   # caller sets box["output"], box["usage"]
    finally:
        usage = box.get("usage")
        emit({
            "run_id": run_id,
            "handoff_id": span_id,
            "seq": seq,
            "from": "loop",
            "to": name,
            "parent_handoff_id": parent,
            "duration_ms": (time.monotonic_ns() - t0) // 1_000_000,
            "input_rendered_ref": put_blob(f"{run_id}/{span_id}.in.txt", rendered_input),
            "output_rendered_ref": put_blob(
                f"{run_id}/{span_id}.out.json", json.dumps(box.get("output"))),
            "usage": None if usage is None else {
                "input_tokens": usage.input_tokens,
                "cache_read_input_tokens": usage.cache_read_input_tokens,
                "cache_creation_input_tokens": usage.cache_creation_input_tokens,
                "output_tokens": usage.output_tokens,
            },
            "config": {"model": MODEL, "effort": EFFORT, "prompt_pack": PACK},
        })


def review(contract_ref: str) -> dict:
    run_id = f"run_{uuid.uuid4().hex[:10]}"
    messages, prev = [], None
    for seq, name in enumerate(["plan", "classify", "extract", "check", "draft"], start=1):
        rendered = render(name, messages, contract_ref)
        with phase(run_id, name, seq, rendered, prev) as box:
            resp = client.messages.create(
                model=MODEL, max_tokens=16000,
                output_config={"effort": EFFORT},
                system=SYSTEM, messages=messages + [{"role": "user", "content": rendered}],
            )
            box["usage"], box["output"] = resp.usage, extract_json(resp)
            messages += [{"role": "user", "content": rendered},
                         {"role": "assistant", "content": resp.content}]
        prev = f"ph-{seq}"
    return assemble(messages)

rendered is the point of the whole listing. It is the exact string the phase was given after every substitution, which is the field chapter 3 established as the difference between a trace you can reason about and a prompt template you cannot. The loop has that string in hand at the moment it builds the request; persisting it is one function call.

Replay works the same way it does for the pipeline. Load input_rendered_ref, send it with the recorded config, compare against output_rendered_ref. The one place the loop is genuinely harder is replaying phase four in isolation, because phase four's real input is the accumulated messages array rather than just rendered — so the honest version persists the full array, which on this workload adds about 90 KB per run.

Two trace trees carrying the same information

Flowchart: run_01H · 71s · $4.10 → classify · 9s · 14.2k tok; run_01H · 71s · $4.10 → extract · 31s · 68.9k tok; run_01H · 71s · $4.10 → draft · 17s · 42.1k tok; run_01H · 71s · $4.10 → pgap (boundary latency 14.2s p95); run_02K · 44s · $1.52 → plan · 3s · 9.8k; run_02K · 44s · $1.52 → classify · 8s · 12.6k; run_02K · 44s · $1.52 → extract · 19s · 24.3k; run_02K · 44s · $1.52 → check · 7s · 11.1k; run_02K · 44s · $1.52 → draft · 7s · 13.4k.

Both trees carry a named unit, a duration, a token count and a content reference per node. The loop's tree has more nodes, because five phases are more granular than three agents, and it has no boundary-latency edges, because there are no boundaries. An on-call engineer looking at the right-hand tree has strictly more information than one looking at the left, at a third of the cost.

The same defect, diagnosed twice

Abstract claims about observability are hard to argue with, so it is worth walking one real ticket through both systems. A summary for a logistics agreement omitted a supplier-side audit-rights obligation in clause 22.4. The lawyer flagged it; the ticket says "missing obligation, contract ID 84-2291".

In the pipeline the engineer opens the trace for that contract's run, sees three spans, and starts at extract because that is where obligations come from. Its output has 47 obligations and none of them is 22.4. Its input is the clause map from classify, which does list clause 22 with the type audit_and_records. So the extractor was told about the clause and did not extract from it. The engineer pulls extract's rendered input, replays it locally, reproduces the miss, notices the clause map truncates at clause 20 in the rendered version despite listing clause 22 in classify's output, and finds a 4,000-character cap in the brief template. Elapsed: about half an hour, most of it replay.

In the uninstrumented loop the engineer has one span saying the run took 41 seconds and used 84,000 tokens, and a debug log that rotated out three days ago. The path from there is to re-run the contract locally, hope the miss reproduces, and if it does, add print statements to a five-turn loop and run it again — twice more, because the first pass printed the wrong thing. If it does not reproduce, the ticket goes to a pile. That is the four and a half hours, and roughly a third of tickets in that pile never got resolved at all.

In the instrumented loop the engineer opens the trace, sees five spans, and starts at extract for the same reason. Everything after that is identical to the pipeline path, with one difference in each direction: the loop's extract span has a finer-grained neighbour on either side, so the truncation would have been visible by diffing classify's output against extract's input without a replay at all; and replaying extract in isolation requires loading the persisted messages array rather than a single rendered string, which is one extra line in the replay harness.

The forty minutes was never about three processes. It was about having a span, an input, and an output at the granularity of the thing that went wrong.

Which debugging properties need the boundary

Not everything the pipeline provides ports for free, and the case for the topology has to be made on the rows that do not.

PropertyPipelineInstrumented loopCost to obtain in the loop
Named unit with durationyesyesone context manager
Exact rendered input persistedyesyesone blob write per phase
Per-step token and cost attributionyesyesalready in usage
Offline replay of one stepyesyespersist the messages array (~90 KB/run)
Restart one step in production from a checkpointyespartialneeds a serialisable loop state
Independent deploy cadence per stepyesnonot obtainable
Distinct credentials or tool scope per stepyespartialmid-conversation tool changes; costs the cache
Horizontal scaling of one hot stepyesnonot obtainable
Different model per stepyespartiala model switch invalidates the prompt cache

Three rows are genuine. Independent deploy cadence matters when different teams own different stages and ship on different schedules — the contract-review service is owned by one team of four, so it does not apply here, and on a larger org chart it would. Horizontal scaling of one hot step matters when one stage is the bottleneck under load and the others are idle; the extract phase is 43% of this run's wall-clock, which is not enough asymmetry to justify separate scaling but would be at 90%. Hard permission isolation matters when one stage should hold credentials the others must not — on the payables pipeline from chapter 1 the extractor is the only stage that touches the raw document store, and an argument that it should therefore run with a scoped credential nothing else in the run holds is a real argument that survives everything in this topic.

What none of those three rows is, is the trace view. The two on-call engineers were arguing for row one through four and being charged for rows six through eight, which their service does not use.

Pricing the choice properly

The contract-review service handles about 3,800 reviews a month. At $4.10 per successful review the pipeline bills $15,580 a month; the chunked loop at $1.52 bills $5,776. The difference is $9,804 a month, or roughly $118,000 a year, plus 27 seconds of p95 latency on every review a lawyer is waiting for.

The logging work is the code above plus a blob-store bucket plus a dashboard query, which the engineer who wrote it estimated at a day and a half. Stating the choice as "$118,000 a year and 27 seconds of p95 against a day and a half of logging work" is not a rhetorical trick; it is what the two options are, once the debugging gain is attributed to the thing that produced it. The meeting ended in about six minutes after somebody wrote those two figures next to each other.

The same framing works in reverse, and it is worth applying honestly. If the loop's instrumentation had turned out to cost two engineer-months — if, say, the service's phases were not cleanly separable and extracting them meant restructuring the prompt — then $118,000 a year against two months of work is a much closer call, and might come out the other way for a year. The point is to compute the trade, not to assume its answer.

Granularity is a knob, and finer is not free

One thing the instrumented loop makes obvious, which the pipeline hides, is that span granularity is a choice rather than a consequence. The loop has five phases because someone decided on five; it could have twelve, one per tool call, or three. The pipeline has three spans because it has three processes, and changing that number means changing the deployment.

Finer is better for debugging up to a point and then stops being. At one span per model call this service emits about 19 spans per run and 72,000 spans a day, which is comfortable. At one span per tool call it emits closer to 140 per run and just over half a million a day, at which point the trace UI's default query gets slow, retention costs become a line item, and — the actual problem — the on-call engineer scrolling a 140-node tree is doing the same work they were doing in the debug log, with better formatting.

The useful granularity is the granularity at which failures are attributed, and that is a property of how the work decomposes rather than of how it is deployed. On this service the answer is phases, because "the extractor missed a clause" and "the classifier mislabelled a clause" are different tickets with different fixes, and "tool call 7 of 19 returned slowly" is not a ticket at all. Tool-call timing still gets recorded, as attributes on the phase span rather than as spans of its own, which keeps it queryable without putting it in the tree.

That the pipeline gets its granularity for free is a genuine convenience and a genuine constraint. The team could not have split extract into two spans without splitting it into two services, and when they later wanted to separate clause location from obligation phrasing, that is exactly what they had to argue about.

The forcing function is the part that does not port

There is one real thing the pipeline had that the instrumented loop does not, and it is not on the table above. In the pipeline, an agent that did not persist its input could not run at all, because the orchestrator had to serialise something to hand it. In the loop, the phase context manager is optional. Somebody in a hurry can add a sixth model call outside it, and the trace will be silently incomplete on exactly the runs that go wrong six months from now.

That is a genuine risk and it has a mundane fix, which is to make the instrumented path the only path. The client wrapper is private to the module; the only exported way to make a model call in the service takes a phase name and a rendered input; a CI check greps for direct client.messages calls outside the wrapper and fails the build. That is another half day, and it converts a discipline into a constraint.

Once traces are decoupled from topology, every remaining argument for a stage has to be made on what that stage contributes to the output. That is a much harder argument to make and a much easier one to test, because "does this stage change the result" is a question you can answer by removing it. The last chapter is about doing that on a pipeline someone has asked you to make 40% cheaper.

When multi-agent hurts — read the current version at https://daviddominguez.dev/learn/en/when-multi-agent-hurts/per-step-traces-are-a-logging-feature-not-a-topology

Back to top