diff --git a/CHANGELOG.md b/CHANGELOG.md index c8602af4f..658218361 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Added detailed latency logging to `UserBotLatencyLogObserver`, capturing + average response time between user stop and bot start, as well as minimum and + maximum response latency. + ### Changed - Updated the `pipecat.runner.daily` utility to only a take `DAILY_API_URL` and diff --git a/src/pipecat/observers/loggers/user_bot_latency_log_observer.py b/src/pipecat/observers/loggers/user_bot_latency_log_observer.py index eb699f2bb..505a0a807 100644 --- a/src/pipecat/observers/loggers/user_bot_latency_log_observer.py +++ b/src/pipecat/observers/loggers/user_bot_latency_log_observer.py @@ -7,11 +7,14 @@ """Observer for measuring user-to-bot response latency.""" import time +from statistics import mean from loguru import logger from pipecat.frames.frames import ( BotStartedSpeakingFrame, + CancelFrame, + EndFrame, UserStartedSpeakingFrame, UserStoppedSpeakingFrame, ) @@ -35,6 +38,7 @@ class UserBotLatencyLogObserver(BaseObserver): super().__init__() self._processed_frames = set() self._user_stopped_time = 0 + self._latencies = [] async def on_push_frame(self, data: FramePushed): """Process frames to track speech timing and calculate latency. @@ -56,6 +60,18 @@ class UserBotLatencyLogObserver(BaseObserver): self._user_stopped_time = 0 elif isinstance(data.frame, UserStoppedSpeakingFrame): self._user_stopped_time = time.time() + elif isinstance(data.frame, (EndFrame, CancelFrame)): + if self._latencies: + avg_latency = mean(self._latencies) + min_latency = min(self._latencies) + max_latency = max(self._latencies) + logger.info( + f"⏱️ LATENCY FROM USER STOPPED SPEAKING TO BOT STARTED SPEAKING - Avg: {avg_latency:.3f}s, Min: {min_latency:.3f}s, Max: {max_latency:.3f}s" + ) elif isinstance(data.frame, BotStartedSpeakingFrame) and self._user_stopped_time: latency = time.time() - self._user_stopped_time - logger.debug(f"⏱️ LATENCY FROM USER STOPPED SPEAKING TO BOT STARTED SPEAKING: {latency}") + self._user_stopped_time = 0 + self._latencies.append(latency) + logger.debug( + f"⏱️ LATENCY FROM USER STOPPED SPEAKING TO BOT STARTED SPEAKING: {latency:.3f}s" + )