Merge pull request #2357 from pipecat-ai/filipi/latency_observer

Added detailed latency logging to UserBotLatencyLogObserver.

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

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"
+            )