From 3f7f84e108dab7ced1d490f755dfdc295341845e Mon Sep 17 00:00:00 2001
From: iceteaSA <171169159+iceteaSA@users.noreply.github.com>
Date: Mon, 10 Aug 2026 13:35:20 +0200
Subject: [PATCH] logging: label the perf tick rolling window and emit the
 interval count

The rolling tool-call group sat beside per-interval deltas without identifying its window, which caused a real idle-path stall misdiagnosis. Emit new_tool_calls, already computed as the activity gate, and label the retained ring occupancy as window without draining the rolling samples.
---
 crates/aft/src/logging.rs | 43 +++++++++++++++++++++++++++++++--------
 1 file changed, 34 insertions(+), 9 deletions(-)

diff --git a/crates/aft/src/logging.rs b/crates/aft/src/logging.rs
index 43819c56..b9e5750c 100644
--- a/crates/aft/src/logging.rs
+++ b/crates/aft/src/logging.rs
@@ -568,7 +568,7 @@ struct ToolCallPerfSample {
 
 #[derive(Clone, Copy, Default)]
 struct ToolCallPerfSummary {
-    count: usize,
+    window: usize,
     p50_total_ms: u64,
     max_total_ms: u64,
     p50_queue_ms: u64,
@@ -831,7 +831,7 @@ pub fn perf_tick(executor: Option<&Executor>) {
     };
     let sample = sample.unwrap_or_default();
     crate::slog_info!(
-        "perf tick: watcher={{ingested:{},paths:{},dropped:{}}} drains={} tier2=[{}] semantic={{collects:{},files:{},chunks:{},ms:{}}} callgraph_invalidations={} executor_completed={{interactive:{},maintenance:{}}} oldest_queued_ms={{interactive:{},maintenance:{}}} toolcall={{count:{},p50_total_ms:{},max_total_ms:{},p50_queue_ms:{},max_queue_ms:{}}} file_log_dropped={}",
+        "perf tick: watcher={{ingested:{},paths:{},dropped:{}}} drains={} tier2=[{}] semantic={{collects:{},files:{},chunks:{},ms:{}}} callgraph_invalidations={} executor_completed={{interactive:{},maintenance:{}}} oldest_queued_ms={{interactive:{},maintenance:{}}} {} file_log_dropped={}",
         watcher_ingested,
         watcher_paths,
         watcher_dropped,
@@ -846,11 +846,7 @@ pub fn perf_tick(executor: Option<&Executor>) {
         completed_maintenance,
         format_optional_ms(sample.interactive_oldest_ms),
         format_optional_ms(sample.maintenance_oldest_ms),
-        tool_calls.count,
-        tool_calls.p50_total_ms,
-        tool_calls.max_total_ms,
-        tool_calls.p50_queue_ms,
-        tool_calls.max_queue_ms,
+        format_tool_call_summary(new_tool_calls, tool_calls),
         file_lines_dropped,
     );
 }
@@ -879,7 +875,7 @@ fn summarize_tool_calls(samples: &VecDeque<ToolCallPerfSample>) -> ToolCallPerfS
     queues.sort_unstable();
     let median_index = (samples.len() - 1) / 2;
     ToolCallPerfSummary {
-        count: samples.len(),
+        window: samples.len(),
         p50_total_ms: totals[median_index],
         max_total_ms: totals[totals.len() - 1],
         p50_queue_ms: queues[median_index],
@@ -887,6 +883,17 @@ fn summarize_tool_calls(samples: &VecDeque<ToolCallPerfSample>) -> ToolCallPerfS
     }
 }
 
+fn format_tool_call_summary(new_tool_calls: u64, summary: ToolCallPerfSummary) -> String {
+    format!(
+        "toolcall={{new:{new_tool_calls},window:{},p50_total_ms:{},max_total_ms:{},p50_queue_ms:{},max_queue_ms:{}}}",
+        summary.window,
+        summary.p50_total_ms,
+        summary.max_total_ms,
+        summary.p50_queue_ms,
+        summary.max_queue_ms,
+    )
+}
+
 fn format_optional_ms(value: Option<u64>) -> String {
     value
         .map(|value| value.to_string())
@@ -1056,10 +1063,28 @@ mod tests {
 
         let summary = summarize_tool_calls(&samples);
 
-        assert_eq!(summary.count, 4);
+        assert_eq!(summary.window, 4);
         assert_eq!(summary.p50_total_ms, 5);
         assert_eq!(summary.max_total_ms, 9);
         assert_eq!(summary.p50_queue_ms, 2);
         assert_eq!(summary.max_queue_ms, 5);
     }
+
+    #[test]
+    fn tool_call_tick_labels_interval_count_and_rolling_window() {
+        let samples = VecDeque::from([ToolCallPerfSample {
+            total_ms: 3_000,
+            queue_ms: 2_900,
+        }]);
+        let summary = summarize_tool_calls(&samples);
+
+        assert_eq!(
+            format_tool_call_summary(1, summary),
+            "toolcall={new:1,window:1,p50_total_ms:3000,max_total_ms:3000,p50_queue_ms:2900,max_queue_ms:2900}"
+        );
+        assert_eq!(
+            format_tool_call_summary(0, summary),
+            "toolcall={new:0,window:1,p50_total_ms:3000,max_total_ms:3000,p50_queue_ms:2900,max_queue_ms:2900}"
+        );
+    }
 }