From b3502bd4eab1649c9c0f766d9511b53cc8da7ee9 Mon Sep 17 00:00:00 2001 From: John Tennant Date: Wed, 21 Oct 2026 22:48:51 -0400 Subject: [PATCH 1/3] berd-call: report how long speak held speech and took to be heard A speak result now says, in milliseconds from when the voice session was asked to say it, when the session stopped holding it while you talked (`heldMs`) and when its first audio played (`firstAudioMs`). Hosts can then tell waiting for you, synthesis and playback apart when measuring a call's response latency. Co-authored-by: Damon <8a08290d889f1c68921542bfe9631d4cd671be9bea5f1114951f386819e4c10a@buzz.block.builderlab.xyz> Co-Authored-By: Claude Opus 5.5 Signed-off-by: John Tennant --- src-tauri/crates/berd-call/README.md | 4 +- .../crates/berd-call/src/host_session.rs | 91 +++++++++++++++++++ 2 files changed, 94 insertions(+), 1 deletion(-) diff --git a/src-tauri/crates/berd-call/README.md b/src-tauri/crates/berd-call/README.md index ee08673f8..679cb283f 100644 --- a/src-tauri/crates/berd-call/README.md +++ b/src-tauri/crates/berd-call/README.md @@ -84,7 +84,9 @@ its own speech; headphone-like outputs retain barge-in. `speak` waits for delivery by default. Interrupted results contain `spokenThroughUtf8` and `estimatedSpokenText`, a best-effort prefix of the -submitted text. To return without waiting for delivery, start the call with +submitted text. Results of admitted speech also contain `heldMs`, how long the +call held it while you were talking, and `firstAudioMs`, when its first audio +was played, both in milliseconds from when the call was asked to say it. To return without waiting for delivery, start the call with `--stream --non-blocking`, or change the live session using `berd-call settings --non-blocking true`. Speak calls inherit this setting; they wait for pending speech before attempting admission. The command returns `status: accepted` and a diff --git a/src-tauri/crates/berd-call/src/host_session.rs b/src-tauri/crates/berd-call/src/host_session.rs index 3b9ce4735..d0dec2951 100644 --- a/src-tauri/crates/berd-call/src/host_session.rs +++ b/src-tauri/crates/berd-call/src/host_session.rs @@ -951,6 +951,11 @@ struct PendingSpeak { text: String, non_blocking: bool, response: Option>>, + /// When the voice session was asked to speak, then how long it held the + /// speech while you talked and until its first audio was played. + prepared: Instant, + held_ms: Option, + first_audio_ms: Option, } enum AudioCommand { @@ -1421,6 +1426,9 @@ impl SessionActor { text, non_blocking, response: Some(response), + prepared: Instant::now(), + held_ms: None, + first_audio_ms: None, }); } ControlCommand::Restart { @@ -1608,6 +1616,9 @@ impl SessionActor { SessionMessage::Admitted { id, speech_id, .. } if self.pending_prepare_id() == Some(id) => { + if let Some(pending) = self.pending_speak.as_mut() { + pending.held_ms = Some(pending.prepared.elapsed().as_millis() as u64); + } send_request(&self.writer, &SessionRequest::OutputReady { id, speech_id })?; } SessionMessage::OutputReadyResult { id, outcome, .. } @@ -1623,6 +1634,11 @@ impl SessionActor { } } } + SessionMessage::SpeechStarted { id, .. } if self.pending_prepare_id() == Some(id) => { + if let Some(pending) = self.pending_speak.as_mut() { + pending.first_audio_ms = Some(pending.prepared.elapsed().as_millis() as u64); + } + } SessionMessage::SpeechCompleted { id, .. } if self.pending_prepare_id() == Some(id) => { self.respond_speak(Ok(json!({"spoke":true,"status":"completed"}))); } @@ -1679,6 +1695,19 @@ impl SessionActor { fn respond_speak(&mut self, result: Result) { if let Some(pending) = self.pending_speak.take() { + let result = result.map(|mut value| { + if let Value::Object(fields) = &mut value { + for (key, ms) in [ + ("heldMs", pending.held_ms), + ("firstAudioMs", pending.first_audio_ms), + ] { + if let Some(ms) = ms { + fields.insert(key.into(), ms.into()); + } + } + } + value + }); if let Some(response) = pending.response { let _ = response.send(result); } else { @@ -3909,6 +3938,9 @@ mod tests { text: "first".into(), non_blocking: false, response: Some(first_tx), + prepared: Instant::now(), + held_ms: None, + first_audio_ms: None, }); let (next_tx, next_rx) = mpsc::sync_channel(1); actor @@ -3969,6 +4001,9 @@ mod tests { text: "playing".into(), non_blocking: false, response: Some(playing_tx), + prepared: Instant::now(), + held_ms: None, + first_audio_ms: None, }); let (queued_tx, queued) = mpsc::sync_channel(1); actor @@ -4046,6 +4081,9 @@ mod tests { text: "playing".into(), non_blocking: false, response: Some(playing_tx), + prepared: Instant::now(), + held_ms: None, + first_audio_ms: None, }); let (restart, _restarted) = restart_command(); actor.handle_command(restart).unwrap(); @@ -4334,6 +4372,9 @@ mod tests { text: "playing".into(), non_blocking: false, response: Some(playing_tx), + prepared: Instant::now(), + held_ms: None, + first_audio_ms: None, }); let (restart, restarted) = restart_command(); actor.handle_command(restart).unwrap(); @@ -4348,6 +4389,56 @@ mod tests { assert!(child.wait().unwrap().success()); } + #[test] + fn speak_reports_how_long_speech_was_held_and_took_to_be_heard() { + let mut child = Command::new("/bin/cat") + .stdin(Stdio::piped()) + .stdout(Stdio::null()) + .spawn() + .unwrap(); + let writer = Arc::new(Mutex::new(child.stdin.take().unwrap())); + let (_events_tx, events) = mpsc::sync_channel(1); + let (_commands_tx, commands) = mpsc::sync_channel(1); + let (audio_commands, _audio_rx) = mpsc::sync_channel(1); + let mut actor = test_actor(writer, events, commands, audio_commands); + let (response, result) = mpsc::sync_channel(1); + actor + .handle_command(ControlCommand::Speak { + text: "hello".into(), + acknowledgement: None, + resolved_handoff_ids: Vec::new(), + voice: None, + language: None, + relay: false, + non_blocking: false, + response, + }) + .unwrap(); + let id = actor.pending_prepare_id().unwrap(); + thread::sleep(Duration::from_millis(20)); + actor + .handle_event(SessionMessage::Admitted { + id, + speech_id: 1, + confirmed_token: 0, + }) + .unwrap(); + thread::sleep(Duration::from_millis(20)); + actor + .handle_event(SessionMessage::SpeechStarted { id, speech_id: 1 }) + .unwrap(); + actor + .handle_event(SessionMessage::SpeechCompleted { id, speech_id: 1 }) + .unwrap(); + let result = result.recv().unwrap().unwrap(); + assert_eq!(result["status"], "completed"); + let held = result["heldMs"].as_u64().unwrap(); + assert!(held >= 20); + assert!(result["firstAudioMs"].as_u64().unwrap() >= held + 20); + drop(actor); + assert!(child.wait().unwrap().success()); + } + fn test_snapshot() -> VoiceSessionSnapshot { VoiceSessionSnapshot { spokesperson: None, From 675db4a1c1a229e0d6849d9ed6618c80a72b938d Mon Sep 17 00:00:00 2001 From: John Tennant Date: Wed, 21 Oct 2026 23:07:10 -0400 Subject: [PATCH 2/3] berd-call: say firstAudioMs is when the player accepted the first audio speech_started follows the first accepted PCM chunk, and a suspension can still hold playback after it, so document exactly what is measured. Co-authored-by: Damon <8a08290d889f1c68921542bfe9631d4cd671be9bea5f1114951f386819e4c10a@buzz.block.builderlab.xyz> Co-Authored-By: Claude Opus 5.5 Signed-off-by: John Tennant --- src-tauri/crates/berd-call/README.md | 5 +++-- src-tauri/crates/berd-call/src/host_session.rs | 2 +- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/src-tauri/crates/berd-call/README.md b/src-tauri/crates/berd-call/README.md index 679cb283f..a0527120e 100644 --- a/src-tauri/crates/berd-call/README.md +++ b/src-tauri/crates/berd-call/README.md @@ -85,8 +85,9 @@ its own speech; headphone-like outputs retain barge-in. `speak` waits for delivery by default. Interrupted results contain `spokenThroughUtf8` and `estimatedSpokenText`, a best-effort prefix of the submitted text. Results of admitted speech also contain `heldMs`, how long the -call held it while you were talking, and `firstAudioMs`, when its first audio -was played, both in milliseconds from when the call was asked to say it. To return without waiting for delivery, start the call with +call held it while you were talking, and `firstAudioMs`, when the player accepted +its first audio, both in milliseconds from when the call was asked to say it. +Playback suspended after that, because you started talking, is not included. To return without waiting for delivery, start the call with `--stream --non-blocking`, or change the live session using `berd-call settings --non-blocking true`. Speak calls inherit this setting; they wait for pending speech before attempting admission. The command returns `status: accepted` and a diff --git a/src-tauri/crates/berd-call/src/host_session.rs b/src-tauri/crates/berd-call/src/host_session.rs index d0dec2951..5816f83cc 100644 --- a/src-tauri/crates/berd-call/src/host_session.rs +++ b/src-tauri/crates/berd-call/src/host_session.rs @@ -952,7 +952,7 @@ struct PendingSpeak { non_blocking: bool, response: Option>>, /// When the voice session was asked to speak, then how long it held the - /// speech while you talked and until its first audio was played. + /// speech while you talked and until the player accepted its first audio. prepared: Instant, held_ms: Option, first_audio_ms: Option, From cb87f9650450604992cc6dd58e52f4825d1e0d90 Mon Sep 17 00:00:00 2001 From: John Tennant Date: Thu, 22 Oct 2026 08:49:33 -0400 Subject: [PATCH 3/3] berd-call: log speech timing to stderr instead of the speak result Keep the speak result unchanged and report when speech was admitted and when its first audio was accepted as stderr diagnostics. Co-authored-by: Damon <8a08290d889f1c68921542bfe9631d4cd671be9bea5f1114951f386819e4c10a@buzz.block.builderlab.xyz> Co-Authored-By: Claude Opus 5.5 Signed-off-by: John Tennant --- src-tauri/crates/berd-call/README.md | 5 +- .../crates/berd-call/src/host_session.rs | 92 +++---------------- 2 files changed, 12 insertions(+), 85 deletions(-) diff --git a/src-tauri/crates/berd-call/README.md b/src-tauri/crates/berd-call/README.md index a0527120e..ee08673f8 100644 --- a/src-tauri/crates/berd-call/README.md +++ b/src-tauri/crates/berd-call/README.md @@ -84,10 +84,7 @@ its own speech; headphone-like outputs retain barge-in. `speak` waits for delivery by default. Interrupted results contain `spokenThroughUtf8` and `estimatedSpokenText`, a best-effort prefix of the -submitted text. Results of admitted speech also contain `heldMs`, how long the -call held it while you were talking, and `firstAudioMs`, when the player accepted -its first audio, both in milliseconds from when the call was asked to say it. -Playback suspended after that, because you started talking, is not included. To return without waiting for delivery, start the call with +submitted text. To return without waiting for delivery, start the call with `--stream --non-blocking`, or change the live session using `berd-call settings --non-blocking true`. Speak calls inherit this setting; they wait for pending speech before attempting admission. The command returns `status: accepted` and a diff --git a/src-tauri/crates/berd-call/src/host_session.rs b/src-tauri/crates/berd-call/src/host_session.rs index 5816f83cc..156d37d4e 100644 --- a/src-tauri/crates/berd-call/src/host_session.rs +++ b/src-tauri/crates/berd-call/src/host_session.rs @@ -951,11 +951,8 @@ struct PendingSpeak { text: String, non_blocking: bool, response: Option>>, - /// When the voice session was asked to speak, then how long it held the - /// speech while you talked and until the player accepted its first audio. + /// When the voice session was asked to speak, for timing diagnostics. prepared: Instant, - held_ms: Option, - first_audio_ms: Option, } enum AudioCommand { @@ -1427,8 +1424,6 @@ impl SessionActor { non_blocking, response: Some(response), prepared: Instant::now(), - held_ms: None, - first_audio_ms: None, }); } ControlCommand::Restart { @@ -1616,8 +1611,11 @@ impl SessionActor { SessionMessage::Admitted { id, speech_id, .. } if self.pending_prepare_id() == Some(id) => { - if let Some(pending) = self.pending_speak.as_mut() { - pending.held_ms = Some(pending.prepared.elapsed().as_millis() as u64); + if let Some(pending) = &self.pending_speak { + eprintln!( + "berd-call: speech admitted after {} ms", + pending.prepared.elapsed().as_millis() + ); } send_request(&self.writer, &SessionRequest::OutputReady { id, speech_id })?; } @@ -1635,8 +1633,11 @@ impl SessionActor { } } SessionMessage::SpeechStarted { id, .. } if self.pending_prepare_id() == Some(id) => { - if let Some(pending) = self.pending_speak.as_mut() { - pending.first_audio_ms = Some(pending.prepared.elapsed().as_millis() as u64); + if let Some(pending) = &self.pending_speak { + eprintln!( + "berd-call: speech first audio accepted after {} ms", + pending.prepared.elapsed().as_millis() + ); } } SessionMessage::SpeechCompleted { id, .. } if self.pending_prepare_id() == Some(id) => { @@ -1695,19 +1696,6 @@ impl SessionActor { fn respond_speak(&mut self, result: Result) { if let Some(pending) = self.pending_speak.take() { - let result = result.map(|mut value| { - if let Value::Object(fields) = &mut value { - for (key, ms) in [ - ("heldMs", pending.held_ms), - ("firstAudioMs", pending.first_audio_ms), - ] { - if let Some(ms) = ms { - fields.insert(key.into(), ms.into()); - } - } - } - value - }); if let Some(response) = pending.response { let _ = response.send(result); } else { @@ -3939,8 +3927,6 @@ mod tests { non_blocking: false, response: Some(first_tx), prepared: Instant::now(), - held_ms: None, - first_audio_ms: None, }); let (next_tx, next_rx) = mpsc::sync_channel(1); actor @@ -4002,8 +3988,6 @@ mod tests { non_blocking: false, response: Some(playing_tx), prepared: Instant::now(), - held_ms: None, - first_audio_ms: None, }); let (queued_tx, queued) = mpsc::sync_channel(1); actor @@ -4082,8 +4066,6 @@ mod tests { non_blocking: false, response: Some(playing_tx), prepared: Instant::now(), - held_ms: None, - first_audio_ms: None, }); let (restart, _restarted) = restart_command(); actor.handle_command(restart).unwrap(); @@ -4373,8 +4355,6 @@ mod tests { non_blocking: false, response: Some(playing_tx), prepared: Instant::now(), - held_ms: None, - first_audio_ms: None, }); let (restart, restarted) = restart_command(); actor.handle_command(restart).unwrap(); @@ -4389,56 +4369,6 @@ mod tests { assert!(child.wait().unwrap().success()); } - #[test] - fn speak_reports_how_long_speech_was_held_and_took_to_be_heard() { - let mut child = Command::new("/bin/cat") - .stdin(Stdio::piped()) - .stdout(Stdio::null()) - .spawn() - .unwrap(); - let writer = Arc::new(Mutex::new(child.stdin.take().unwrap())); - let (_events_tx, events) = mpsc::sync_channel(1); - let (_commands_tx, commands) = mpsc::sync_channel(1); - let (audio_commands, _audio_rx) = mpsc::sync_channel(1); - let mut actor = test_actor(writer, events, commands, audio_commands); - let (response, result) = mpsc::sync_channel(1); - actor - .handle_command(ControlCommand::Speak { - text: "hello".into(), - acknowledgement: None, - resolved_handoff_ids: Vec::new(), - voice: None, - language: None, - relay: false, - non_blocking: false, - response, - }) - .unwrap(); - let id = actor.pending_prepare_id().unwrap(); - thread::sleep(Duration::from_millis(20)); - actor - .handle_event(SessionMessage::Admitted { - id, - speech_id: 1, - confirmed_token: 0, - }) - .unwrap(); - thread::sleep(Duration::from_millis(20)); - actor - .handle_event(SessionMessage::SpeechStarted { id, speech_id: 1 }) - .unwrap(); - actor - .handle_event(SessionMessage::SpeechCompleted { id, speech_id: 1 }) - .unwrap(); - let result = result.recv().unwrap().unwrap(); - assert_eq!(result["status"], "completed"); - let held = result["heldMs"].as_u64().unwrap(); - assert!(held >= 20); - assert!(result["firstAudioMs"].as_u64().unwrap() >= held + 20); - drop(actor); - assert!(child.wait().unwrap().success()); - } - fn test_snapshot() -> VoiceSessionSnapshot { VoiceSessionSnapshot { spokesperson: None,