Skip to content

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

Closed

Description

@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.

Activity

  1. ualtinok commented on Aug 10, 2026

    @ualtinok
    Collaborator

    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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions