You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
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 #206
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.
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:
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:
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:
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.
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.
Activity
ualtinok commentedon Aug 10, 2026
Verified against
logging.rs— the report is exact on all three points:summarize_tool_callsruns over the full ring while every sibling field on the tick line is aswap(0)per-interval delta, andnew_tool_callsis 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:
new:(first field in the group).count→windowso the rolling fields self-describe:toolcall={new:3,window:256,p50_total_ms:...,max_total_ms:...,p50_queue_ms:...,max_queue_ms:...}.Shape notes so it lands first-pass: the change is the format string + threading
new_tool_callsthrough to the emit site (it's already in scope as the gate), plus a test asserting the emitted line carries bothnew:andwindow:with the right semantics (a slow call injected in tick N still reports in tick N+1's window whilenew: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.