perf tick: `toolcall={count,...}` is a rolling 256-sample window sitting next to per-interval fields, and the per-interval count is computed then discarded

[iceteaSA]

The toolcall={} group in the perf tick reads as per-interval next to fields that genuinely are, and isn't. It cost a consumer of ours a wrong diagnosis this morning.

toolcall={count:256,p50_total_ms:0,max_total_ms:3012,p50_queue_ms:0,max_queue_ms:4}

summarize_tool_calls runs over the whole VecDeque (TOOL_CALL_SAMPLE_CAPACITY = 256, pop_front when full), and nothing drains it per tick. So count is the ring's occupancy, and p50/max describe the last ≤256 calls whenever they happened — while watcher={ingested,paths,dropped}, semantic={}, and callgraph_invalidations on the same line all use swap(0) and are true per-interval deltas.

What that looks like in a log, once the ring saturates:

08:12:35  max_total_ms:8032   08:13:35  max_total_ms:8032   08:14:35  max_total_ms:8032
08:15:35  max_total_ms:8032   08:16:35  max_total_ms:8024   ...      08:21:36  max_total_ms:8024

One slow call, re-reported every tick until it ages out. Across 743 ticks in one instance's log, max_total_ms took 133 distinct values and count took two (221 and 256). Someone sweeping our shared journal read four consecutive ~3.0s maxima during idle hours as four idle-path stalls and flagged a latency regression. There wasn't one — it was a single earlier slow call aging through the window. The tell that resolved it was max_queue_ms staying flat, which is the discriminator you'd only think to check after already suspecting the metric.

The per-interval number already exists. note_tool_call_trace bumps PERF.tool_call_count, and the reporter computes:

tool_call_count.saturating_sub(reporter.last_tool_call_count)   // → new_tool_calls

new_tool_calls is then used solely as an activity gate for whether to emit the tick at all, and never printed. Emitting it alongside the window would make the line self-describing at nearly zero cost:

toolcall={new:3,window:256,p50_total_ms:0,max_total_ms:8032,...}

Any of three would fix it — emit new_tool_calls, rename count to something that doesn't read per-interval (window/samples), or drain the ring per tick. The first is the smallest and keeps the rolling percentiles, which are genuinely useful for spotting a slow call you'd otherwise miss between ticks.

Happy to send a PR if you want it; it's a few lines in logging.rs plus a test. Same class as #199 — not a correctness bug, a metric whose shape invites a confident wrong reading, which matters more now that several consumers read these ticks out of one shared journal.

[ualtinok]

Verified against logging.rs — the report is exact on all three points: summarize_tool_calls runs over the full ring while every sibling field on the tick line is a swap(0) per-interval delta, and new_tool_calls is computed as the emit gate then discarded. Your 133-distinct-values-across-743-ticks observation is the shape of the problem in one number, and the misread it produced is fair grief: a rolling max sitting unlabeled next to interval deltas invites exactly that diagnosis.

Take both of your first two options together, and we'd welcome the PR:

• Emit the already-computed per-interval count as new: (first field in the group).
• Rename count → window so the rolling fields self-describe: toolcall={new:3,window:256,p50_total_ms:...,max_total_ms:...,p50_queue_ms:...,max_queue_ms:...}.
• Keep the rolling percentiles as-is — you're right that they catch slow calls that land between ticks, and draining the ring would lose that.

Shape notes so it lands first-pass: the change is the format string + threading new_tool_calls through to the emit site (it's already in scope as the gate), plus a test asserting the emitted line carries both new: and window: with the right semantics (a slow call injected in tick N still reports in tick N+1's window while new: reads 0). Line-prefix consumers are unaffected — the shared-journal parser keys on prefixes, not this group's field names — but flag the rename in the PR description anyway for anyone parsing field names.

Same class as #199 indeed, and these reports have all been worth more than their word count. Thanks.