Show where reply time goes after Buzz receives an agent @mention

benchmarks/agent-reply-latency/README.md

@@ -0,0 +1,82 @@
+# Agent mention-to-reply latency
+
+`buzz-acp` emits a content-free `mention_reply_latency` observer event after it
+has seen both the first self-authored reply on the relay and `turn_completed`.
+The event contains one sample plus rolling p50, p95, and max summaries for the
+most recent 100 samples on the same warm or cold path.
+
+This first slice measures `harness_relay_receipt` to
+`harness_relay_fanout`, recorded explicitly as `measurementStart` and
+`measurementEnd`. It does not yet claim sender-publish-to-recipient-render
+end-to-end timing.
+
+## Boundaries
+
+All duration math uses `monotonicMs`, a process-local monotonic clock. RFC3339
+timestamps and Nostr `created_at` values are correlation metadata only and must
+not be used for cross-process duration math.
+
+| Metric | Start | End |
+| --- | --- | --- |
+| `receiveToQueueMs` | relay frame accepted by `buzz-acp` | event admitted to the channel queue |
+| `queueWaitMs` | event admitted to the channel queue | turn task started |
+| `sessionResolveMs` | turn task started | ACP session created or reused |
+| `postSessionSetupMs` | ACP session created or reused | ACP `session/prompt` written |
+| `turnSetupMs` | turn task started | ACP `session/prompt` written |
+| `timeToFirstOutputMs` | ACP `session/prompt` written | first semantic ACP model/tool output frame |
+| `firstOutputToReplyMs` | first semantic ACP model/tool output frame | first self-authored kind-9 reply observed on the relay |
+| `turnDurationMs` | turn task started | turn task completed |
+| `totalMs` | relay frame accepted by `buzz-acp` | first self-authored kind-9 reply observed on the relay |
+
+`path` is `cold` when the turn created a new ACP session, `warm` when it reused
+one, and `unknown` when session resolution was not observed. Summaries never mix
+these paths.
+
+## Deterministic check
+
+The unit fixture drives fixed semantic boundaries through the collector and
+asserts stage math, nearest-rank percentiles, warm/cold separation, flat-thread
+correlation, trace expiry, and content redaction:
+
+```bash
+. ./bin/activate-hermit
+cargo test -p buzz-acp latency --no-fail-fast
+cargo test -p buzz-acp observer_emits_derived_latency_sample --no-fail-fast
+```
+
+## Live benchmark
+
+Managed Desktop agents already start with `BUZZ_ACP_RELAY_OBSERVER=true`. For a
+standalone harness, set that variable and make sure the agent has a resolvable
+owner so encrypted observer frames can be published. Keep the default
+`--ignore-self` behavior enabled; that lets mention-only subscriptions observe
+self-authored replies for telemetry without routing them back into the agent.
+
+1. Record the Buzz commit, relay, agent runtime, provider, model, machine, and
+   network condition.
+2. Open the managed-agent session's raw event rail.
+3. Send a fixed prompt such as `Reply with exactly: pong.` and wait for its
+   `mention_reply_latency` event before sending the next trial.
+4. For warm trials, reuse the same channel session. For cold trials, issue
+   `!rotate`, wait for rotation to finish, then send the fixed prompt.
+5. Run at least 20 sequential trials per path. Read the last event for each path;
+   its `summary` contains `windowSize` and per-stage `samples`, `p50`, `p95`, and
+   `max` in milliseconds.
+
+Keep real-provider runs scheduled or opt-in rather than merge-blocking. Provider
+startup, credentials, cost, network conditions, and relay placement make those
+runs useful operational evidence but unsuitable as deterministic CI.
+
+## Privacy and current scope
+
+Semantic latency events include IDs, path classification, durations, and sample
+counts. They do not include message content, prompts, model output, credentials,
+or tool arguments. Existing raw `acp_read`/`acp_write` observer events retain
+their current behavior and are outside this telemetry's redaction guarantee.
+
+The start boundary is harness receipt, not the sender's publish timestamp. The
+final reply boundary is relay fanout back to the harness, not the Buzz CLI's
+publish-start timestamp or a separate recipient's render timestamp. This first
+instrumentation change establishes a measurable baseline; issue #2386 should
+remain open until the missing outer boundaries, production baselines, explicit
+budgets, and a regression job are landed.

crates/buzz-acp/README.md

@@ -251,6 +251,15 @@ Each channel has at most one prompt in flight. Multiple channels can be processe
 
 > **Note:** On startup, the harness replays all unprocessed @mentions since the last run. Expect a burst of activity if there are stale events in the channel.
 
+### Agent response timing
+
+With `BUZZ_ACP_RELAY_OBSERVER=true`, the observer feed includes content-free
+`mention_reply_latency` samples and rolling warm/cold p50, p95, and max stage
+summaries. See the
+[mention-to-reply benchmark](../../benchmarks/agent-reply-latency/README.md) for
+the event boundaries, repeatable live procedure, privacy scope, and current
+limitations.
+
 ## Using Any ACP Agent
 
 The harness works with any agent that implements the [ACP spec](https://agentclientprotocol.com/) over stdio. The requirements are:

crates/buzz-acp/src/acp.rs

@@ -172,6 +172,10 @@ pub struct AcpClient {
     observer_agent_index: Option<usize>,
     /// Best-effort context attached to raw ACP wire events.
     observer_context: ObserverContext,
+    /// Whether the current prompt has produced its first semantic ACP frame.
+    /// Reset immediately before each `session/prompt` write so cancel cleanup
+    /// cannot emit a duplicate first-output boundary.
+    first_turn_output_observed: bool,
     /// Most recently observed `_meta.goose.activeRunId` from a
     /// `session/update` notification of kind `session_info_update`.
     ///
@@ -489,6 +493,7 @@ impl AcpClient {
             observer: None,
             observer_agent_index: None,
             observer_context: ObserverContext::default(),
+            first_turn_output_observed: false,
             active_run_id: None,
             steer_rx: None,
             goose_usage: UsageTracker::default(),
@@ -684,6 +689,7 @@ impl AcpClient {
         // prompt so that any setup notifications recorded earlier are not
         // misattributed to this turn.
         self.goose_usage.begin_turn(session_id);
+        self.first_turn_output_observed = false;
 
         self.last_prompt_id = Some(self.next_id);
         let id = self.next_id;
@@ -702,6 +708,7 @@ impl AcpClient {
             self.current_hard_deadline = None;
             return Err(e);
         }
+        self.observe("prompt_dispatched", serde_json::json!({ "requestId": id }));
 
         let result = self
             .read_until_response_with_idle_timeout(
@@ -1407,6 +1414,10 @@ impl AcpClient {
                             continue;
                         }
                     };
+                    if !self.first_turn_output_observed && is_semantic_turn_output(&msg) {
+                        self.first_turn_output_observed = true;
+                        self.observe("turn_first_output", serde_json::json!({}));
+                    }
                     self.observe("acp_read", msg.clone());
 
                     let activity_now = Instant::now();
@@ -1760,6 +1771,26 @@ impl AcpClient {
     }
 }
 
+/// Whether an ACP frame represents the first model/tool output for the current
+/// turn. Lifecycle, usage, keepalive, and capability updates are intentionally
+/// excluded so they cannot make time-to-first-output look artificially fast.
+fn is_semantic_turn_output(msg: &serde_json::Value) -> bool {
+    if msg.get("method").and_then(|value| value.as_str()) != Some("session/update") {
+        return false;
+    }
+
+    matches!(
+        msg["params"]["update"]["sessionUpdate"].as_str(),
+        Some(
+            "agent_message_chunk"
+                | "agent_thought_chunk"
+                | "tool_call"
+                | "tool_call_update"
+                | "plan"
+        )
+    )
+}
+
 /// Build `session/prompt` params from one or more text content blocks.
 fn build_prompt_params(session_id: &str, prompt_blocks: &[&str]) -> serde_json::Value {
     let blocks: Vec<serde_json::Value> = prompt_blocks
@@ -2590,6 +2621,77 @@ mod tests {
             .expect("failed to spawn test script")
     }
 
+    #[tokio::test]
+    async fn prompt_emits_content_free_dispatch_and_first_output_boundaries() {
+        let script = r#"
+IFS= read -r line
+printf '%s\n' '{"jsonrpc":"2.0","method":"session/update","params":{"sessionId":"test-session","update":{"sessionUpdate":"keepalive"}}}'
+printf '%s\n' '{"jsonrpc":"2.0","method":"session/update","params":{"sessionId":"test-session","update":{"sessionUpdate":"agent_message_chunk","content":{"type":"text","text":"private model output"}}}}'
+printf '%s\n' '{"jsonrpc":"2.0","id":0,"result":{"stopReason":"end_turn"}}'
+"#;
+        let mut client = spawn_script(script).await;
+        let observer = ObserverHandle::in_process();
+        client.set_observer(Some(observer.clone()), 0);
+        client.set_observer_context(crate::observer::context_for_turn(
+            None,
+            Some("test-session".into()),
+            "turn-1".into(),
+            "2026-07-22T00:00:00Z".into(),
+        ));
+
+        let result = client
+            .session_prompt_with_idle_timeout(
+                "test-session",
+                "private prompt",
+                std::time::Duration::from_secs(1),
+                std::time::Duration::from_secs(5),
+            )
+            .await;
+        assert_eq!(result.unwrap(), StopReason::EndTurn);
+
+        let events = observer.snapshot();
+        let semantic: Vec<_> = events
+            .iter()
+            .filter(|event| event.kind == "prompt_dispatched" || event.kind == "turn_first_output")
+            .collect();
+        assert_eq!(
+            semantic
+                .iter()
+                .filter(|event| event.kind == "prompt_dispatched")
+                .count(),
+            1
+        );
+        assert_eq!(
+            semantic
+                .iter()
+                .filter(|event| event.kind == "turn_first_output")
+                .count(),
+            1
+        );
+        let first_output = semantic
+            .iter()
+            .find(|event| event.kind == "turn_first_output")
+            .expect("first semantic output boundary");
+        let keepalive = events
+            .iter()
+            .find(|event| {
+                event.kind == "acp_read"
+                    && event.payload["params"]["update"]["sessionUpdate"] == "keepalive"
+            })
+            .expect("keepalive raw observer frame");
+        assert!(
+            keepalive.seq < first_output.seq,
+            "keepalive must not close the first semantic output boundary"
+        );
+        assert!(semantic.windows(2).all(|pair| {
+            pair[0].monotonic_ms <= pair[1].monotonic_ms && pair[0].seq < pair[1].seq
+        }));
+
+        let serialized = serde_json::to_string(&semantic).unwrap();
+        assert!(!serialized.contains("private prompt"));
+        assert!(!serialized.contains("private model output"));
+    }
+
     #[tokio::test]
     async fn idle_timeout_fires_on_silent_process() {
         let mut client = spawn_script("sleep 10").await;