The span that answered a question it never measured

I made a code-review agent record every tool call it made and how long each one took. Then I used that trace to conclude the agent never ran tools in parallel.

I have withdrawn that conclusion. Not because the data was wrong, but because I wrote the numbers myself and then read them as measurements.

The instrumentation

const calls = toolCalls.map((c, i) => ({
  ...c,
  gapMs: (toolCalls[i + 1]?.at ?? endedAtFallback) - c.at,
}));
trace.step({ startedAt: c.at, endedAt: c.at + c.gapMs });

Each span's end is pinned to the start of the next call. When the tool actually finished is not used.

That gives the data two properties:

sum of span durations  ==  first start to last end
gap between spans      ==  0

Both are true by construction. They come out that way no matter what happened.

What I did with it

I used this to decide whether tools ran concurrently. The reasoning was fine in isolation: if tools overlap, spans overlap, so the sum of durations should exceed the wall-clock window. I ran the query:

trace          calls   sum of spans   wall clock
c605bf…         88       881s            882s
6561f8…         83       538s            538s
72a4a8…         74       524s            523s

Three traces agreeing to within a second. I read that as zero overlap, therefore fully sequential, and drafted a plan around it: induce parallel tool calls, get a large speedup.

All of it void. The sum matching the window is arithmetic, not observation. And the agreement to three significant figures should itself have been the tell. Real independent measurements do not line up that cleanly.

Only one recorded value was untouched

The start time of each call. Nothing derived it; it is when the event arrived. The gap between two consecutive starts tells you whether the model took a turn in between.

1,093 consecutive call gaps
  one trace's calls, start-time deltas, 0 ≤ gap < 3600s, one day
 
  < 0.3s      51   ( 5%)   dispatched together, parallel
  0.3–3s     422   (39%)   ambiguous
  ≥ 3s       620   (57%)   a model turn in between, sequential
median 3.94s

5% were already going out in parallel. "Fully sequential" was not merely wrong by some margin; it was wrong in direction. I did not fail to see something absent. I read something present as zero.

Those counts are the ones I can reproduce. The first version of this post carried 1,025 / 49 / 383 / 593 and a median of 4.1s, and re-running the same definition returns 1,093 / 51 / 422 / 620 and 3.94s. The proportions barely move and the conclusion does not move at all, but I cannot account for the 68-call difference: I did not write down the original query, so I cannot tell whether the filter differed or whether I measured before the day's last traces had landed.

In a post about checking where a number came from, a number I cannot re-derive does not get to stay. The figures above are the reproducible ones, and the filter is stated with them: gap < 3600s exists because without it one boundary artefact reports 1.7 billion seconds and swamps the distribution.

Why this is worse than no instrumentation

With no instrumentation the screen is blank, and people notice blank. Fabricated instrumentation answers. If the answer is plausible you build on it, and nothing in the trace says which fields were measured and which were computed.

Cutting the instrumentation in was the right call on its own. Before it, the agent was a subprocess the outer tracing never entered, and all a trace could say about a stage was "this took 191 seconds." Opening it up made the tool calls visible, and half of what became visible was calculated.

That is the narrower version of a problem I have written about before: there, the tracing integration produced a full dashboard and no traces at all from the components that make decisions. Here it reached them and filled half the fields itself.

How you would catch it

Two signals, both of which I saw late.

One: two numbers agree too well. 881 against 882, 538 against 538. Two quantities measured independently do not match to three figures. When they do, they are not independent.

Two: there is no distribution. Every gap was zero. When a thousand values in a real system land on exactly one number, that is not a measurement, it is a constant.

Inferred, not measured: I have not turned these two signals into a rule and run it against other traces. This is one case, recognised after the fact.

What to take from it

When you read a trace field, check where the value came from. A field named endedAt reads like the time something ended, but the code that matters is not the code consuming it. It is the code writing it.

And when you add instrumentation, write down the question you think it now answers, then check that the values that question needs are actually the ones being recorded. I wanted to ask "is this parallel?" What got recorded was "how many calls were there?" The field existed. The answer did not.

The same shape as scoring a strategy that ignores the input: the number comes back, it is well-formed, and it is not about what you think it is about.

A note on the counts

The 1,025 gaps above are consecutive-call start times from the traces recorded at the time of this measurement. Elsewhere I quote a 197-call sample from a single 70-minute window on a later day; those are different sets, and the later one carries a field this one did not have: the real tool duration alongside the round trip. The fix for this defect is what made that second field exist.