[真实流程计时]：完成完整链路耗时输出，包含命令时间、LLM发送时间和阶段响应耗时

src/owner_voice_pet/real_live_check.py

@@ -1,5 +1,8 @@
 from __future__ import annotations
 
+import time
+from contextlib import contextmanager
+from datetime import datetime
 import subprocess
 import tempfile
 import wave
@@ -29,6 +32,85 @@ DEFAULT_QUESTIONS = [
     "我叫阿明，请你记住我的名字。",
     "我叫什么名字？",
 ]
+STAGE_PAIRS = [
+    ("wake_wait", "wake_listening", "wake_detected"),
+    ("acknowledgement", "ack_started", "question_prompt"),
+    ("wait_for_speech", "capture_started", "speech_started"),
+    ("capture", "speech_started", "speech_ended"),
+    ("final_stt", "stt_started", "transcript_final"),
+    ("llm_to_first_tts", "llm_started", "tts_started"),
+    ("turn_total", "wake_listening", "standby_resumed"),
+]
+
+
+def _now_iso() -> str:
+    return datetime.now().astimezone().isoformat(timespec="milliseconds")
+
+
+def _epoch_ms() -> int:
+    return int(time.time() * 1000)
+
+
+def _elapsed_ms(start: float, end: float | None = None) -> int:
+    return int(round(((end if end is not None else time.perf_counter()) - start) * 1000))
+
+
+class TimingRecorder:
+    def __init__(self) -> None:
+        self.started_at = _now_iso()
+        self.started_epoch_ms = _epoch_ms()
+        self._started_mono = time.perf_counter()
+        self.finished_at: str | None = None
+        self.finished_epoch_ms: int | None = None
+        self.duration_ms: int | None = None
+        self.phases: list[dict[str, object]] = []
+        self.events: list[dict[str, object]] = []
+
+    @contextmanager
+    def phase(self, name: str) -> Iterable[None]:
+        started_mono = time.perf_counter()
+        record: dict[str, object] = {
+            "name": name,
+            "started_at": _now_iso(),
+            "start_offset_ms": _elapsed_ms(self._started_mono, started_mono),
+        }
+        try:
+            yield
+        finally:
+            finished_mono = time.perf_counter()
+            record["finished_at"] = _now_iso()
+            record["duration_ms"] = _elapsed_ms(started_mono, finished_mono)
+            self.phases.append(record)
+
+    def record_event(self, event_type: str, *, turn_id: int | None, message: str) -> None:
+        self.events.append(
+            {
+                "type": event_type,
+                "turn": turn_id,
+                "at": _now_iso(),
+                "offset_ms": _elapsed_ms(self._started_mono),
+                "message": message,
+            }
+        )
+
+    def finish(self) -> None:
+        self.finished_at = _now_iso()
+        self.finished_epoch_ms = _epoch_ms()
+        self.duration_ms = _elapsed_ms(self._started_mono)
+
+    def to_json(self) -> dict[str, object]:
+        if self.duration_ms is None:
+            self.finish()
+        return {
+            "started_at": self.started_at,
+            "started_epoch_ms": self.started_epoch_ms,
+            "finished_at": self.finished_at,
+            "finished_epoch_ms": self.finished_epoch_ms,
+            "duration_ms": self.duration_ms,
+            "phases": self.phases,
+            "events": self.events,
+            "stage_timings": _stage_timings_from_events(self.events),
+        }
 
 
 @dataclass(slots=True)
@@ -50,13 +132,37 @@ class RealLiveCheckReporter:
 
 
 class RecordingLlmProvider:
-    def __init__(self, delegate: OpenAICompatibleLlmProvider) -> None:
+    def __init__(self, delegate: OpenAICompatibleLlmProvider, timing: TimingRecorder) -> None:
         self.delegate = delegate
+        self.timing = timing
         self.calls: list[list[Message]] = []
+        self.request_timings: list[dict[str, object]] = []
 
     def stream_reply(self, messages: Sequence[Message]) -> Iterable[ReplyDelta]:
         self.calls.append(list(messages))
-        yield from self.delegate.stream_reply(messages)
+        sent_mono = time.perf_counter()
+        request_timing: dict[str, object] = {
+            "call_index": len(self.calls),
+            "sent_at": _now_iso(),
+            "sent_offset_ms": _elapsed_ms(self.timing._started_mono, sent_mono),
+            "message_count": len(messages),
+            "last_user_preview": _last_user_preview(messages),
+        }
+        first_delta_mono: float | None = None
+        try:
+            for delta in self.delegate.stream_reply(messages):
+                if first_delta_mono is None and delta.text_delta:
+                    first_delta_mono = time.perf_counter()
+                    request_timing["first_delta_at"] = _now_iso()
+                    request_timing["first_delta_ms"] = _elapsed_ms(sent_mono, first_delta_mono)
+                yield delta
+        finally:
+            finished_mono = time.perf_counter()
+            request_timing["finished_at"] = _now_iso()
+            request_timing["duration_ms"] = _elapsed_ms(sent_mono, finished_mono)
+            if first_delta_mono is None:
+                request_timing["first_delta_ms"] = None
+            self.request_timings.append(request_timing)
 
 
 class FixtureLiveAudioTransport:
@@ -113,66 +219,74 @@ def run_real_live_check(
     questions: list[str] | None = None,
     play_audio: bool = True,
 ) -> dict[str, object]:
+    timing = TimingRecorder()
     if turns <= 0:
         raise ValueError("turns must be positive")
-    selected_questions = _question_list(turns, questions)
-    config = replace(
-        config,
-        speech_provider="local",
-        noise_filter_enabled=True,
-        realtime_transcript_enabled=True,
-        llm_stream=False,
-        post_playback_drain_ms=0,
-    )
-    config.require_llm_credentials()
-    frames = _generated_live_frames(config, turns=turns, voice=voice, wake_text=wake_text, questions=selected_questions)
-    reporter = RealLiveCheckReporter()
-    event_bus = PipelineEventBus()
-    stt = SherpaOnnxSttProvider(str(config.speech_models_dir))
-    tts = MacSayTtsProvider()
-    llm = RecordingLlmProvider(OpenAICompatibleLlmProvider(config, timeout_s=60))
-    transport = FixtureLiveAudioTransport(
-        frames,
-        play_audio=play_audio,
-        output_transport=SoundDeviceAudioTransport(output_device=config.audio_output_device),
-    )
-    pipeline = VoiceAssistantPipeline(
-        config=config,
-        transport=transport,
-        wakeword=SherpaOnnxKeywordWakeWordProvider(
-            config.speech_models_dir,
-            keyword=config.wake_word,
-            keywords_file=config.wake_keywords_file,
-            threshold=config.wake_kws_threshold,
-            score=config.wake_kws_score,
-        ),
-        vad_recorder=PrimarySpeakerVadRecorder(
-            HybridVadProvider(
-                SherpaOnnxVadProvider(config.speech_models_dir, threshold=config.vad_threshold),
-                EnergyVadProvider(),
+    with timing.phase("prepare_config"):
+        selected_questions = _question_list(turns, questions)
+        config = replace(
+            config,
+            speech_provider="local",
+            noise_filter_enabled=True,
+            realtime_transcript_enabled=True,
+            llm_stream=False,
+            post_playback_drain_ms=0,
+        )
+        config.require_llm_credentials()
+    with timing.phase("generate_fixture_audio"):
+        frames = _generated_live_frames(config, turns=turns, voice=voice, wake_text=wake_text, questions=selected_questions)
+    with timing.phase("build_pipeline"):
+        reporter = RealLiveCheckReporter()
+        event_bus = PipelineEventBus()
+        event_bus.subscribe(lambda event: timing.record_event(event.type, turn_id=event.turn_id, message=event.message))
+        stt = SherpaOnnxSttProvider(str(config.speech_models_dir))
+        tts = MacSayTtsProvider()
+        llm = RecordingLlmProvider(OpenAICompatibleLlmProvider(config, timeout_s=60), timing)
+        transport = FixtureLiveAudioTransport(
+            frames,
+            play_audio=play_audio,
+            output_transport=SoundDeviceAudioTransport(output_device=config.audio_output_device),
+        )
+        pipeline = VoiceAssistantPipeline(
+            config=config,
+            transport=transport,
+            wakeword=SherpaOnnxKeywordWakeWordProvider(
+                config.speech_models_dir,
+                keyword=config.wake_word,
+                keywords_file=config.wake_keywords_file,
+                threshold=config.wake_kws_threshold,
+                score=config.wake_kws_score,
             ),
-            min_duration_ms=config.vad_min_duration_ms,
-            end_silence_ms=config.vad_end_silence_ms,
-            no_speech_timeout_ms=config.vad_no_speech_timeout_ms,
-            max_recording_ms=config.vad_max_recording_ms,
-            speaker_profile_ms=config.speaker_profile_ms,
-            speaker_profile_min_ms=config.speaker_profile_min_ms,
-            speaker_absent_ms=config.speaker_absent_ms,
-            similarity_threshold=config.speaker_similarity_threshold,
-            min_rms=config.speaker_min_rms,
-        ),
-        audio_preprocessor=SherpaOnnxDenoiserPreprocessor(config.speech_models_dir),
-        stt=stt,
-        realtime_stt=stt,
-        llm=llm,
-        tts=tts,
-        ack_tts=tts,
-        context=ConversationContext(max_messages=config.context_max_messages, max_chars=config.context_max_chars),
-        reporter=reporter,
-        event_bus=event_bus,
-    )
-    summary = pipeline.run(max_turns=turns)
+            vad_recorder=PrimarySpeakerVadRecorder(
+                HybridVadProvider(
+                    SherpaOnnxVadProvider(config.speech_models_dir, threshold=config.vad_threshold),
+                    EnergyVadProvider(),
+                ),
+                min_duration_ms=config.vad_min_duration_ms,
+                end_silence_ms=config.vad_end_silence_ms,
+                no_speech_timeout_ms=config.vad_no_speech_timeout_ms,
+                max_recording_ms=config.vad_max_recording_ms,
+                speaker_profile_ms=config.speaker_profile_ms,
+                speaker_profile_min_ms=config.speaker_profile_min_ms,
+                speaker_absent_ms=config.speaker_absent_ms,
+                similarity_threshold=config.speaker_similarity_threshold,
+                min_rms=config.speaker_min_rms,
+            ),
+            audio_preprocessor=SherpaOnnxDenoiserPreprocessor(config.speech_models_dir),
+            stt=stt,
+            realtime_stt=stt,
+            llm=llm,
+            tts=tts,
+            ack_tts=tts,
+            context=ConversationContext(max_messages=config.context_max_messages, max_chars=config.context_max_chars),
+            reporter=reporter,
+            event_bus=event_bus,
+        )
+    with timing.phase("pipeline_run"):
+        summary = pipeline.run(max_turns=turns)
+    timing.finish()
     event_counts = Counter(event.type for event in event_bus.events)
+    timing_data = timing.to_json()
     context_messages = [{"role": item.role, "content": item.content[:120]} for item in pipeline.context.messages()]
     checks = {
         "completed_turns": summary.completed_turns == turns,
@@ -184,8 +298,11 @@ def run_real_live_check(
         "tts_per_turn": event_counts["tts_started"] >= turns,
         "playback_per_turn": event_counts["playback_finished"] >= turns,
         "standby_per_turn": event_counts["standby_resumed"] >= turns,
-        "temporary_context_in_second_llm": _second_call_contains_first_turn(llm.calls),
+        "temporary_context_in_second_llm": turns < 2 or _second_call_contains_first_turn(llm.calls),
         "real_output_playback": (not play_audio) or len(transport.played_segments) >= turns * 2,
+        "timing_present": bool(timing_data.get("duration_ms") and timing_data.get("stage_timings")),
+        "llm_request_timing_present": len(llm.request_timings) >= turns
+        and all("sent_at" in item and "duration_ms" in item for item in llm.request_timings),
     }
     return {
         "success": all(checks.values()) and not reporter.errors,
@@ -202,6 +319,8 @@ def run_real_live_check(
         "errors": reporter.errors,
         "play_audio": play_audio,
         "voice": voice,
+        "timing": timing_data,
+        "llm_request_timings": llm.request_timings,
     }
 
 
@@ -337,3 +456,77 @@ def _second_call_contains_first_turn(calls: list[list[Message]]) -> bool:
         return False
     second_contents = "\n".join(message.content for message in calls[1])
     return "我叫阿明" in second_contents and any(message.role == "assistant" for message in calls[1])
+
+
+def _last_user_preview(messages: Sequence[Message]) -> str:
+    for message in reversed(messages):
+        if message.role == "user":
+            return message.content[:80]
+    return ""
+
+
+def _stage_timings_from_events(events: list[dict[str, object]]) -> list[dict[str, object]]:
+    timings: list[dict[str, object]] = []
+    turns = sorted({int(event["turn"]) for event in events if event.get("turn") is not None})
+    for turn_id in turns:
+        turn_events = [event for event in events if event.get("turn") == turn_id]
+        for stage_name, start_type, end_type in STAGE_PAIRS:
+            timing = _pair_timing(turn_events, stage_name, start_type, end_type)
+            if timing is not None:
+                timings.append(timing)
+        timings.extend(_repeated_pair_timings(turn_events, "tts_playback", "tts_started", "playback_finished"))
+    return timings
+
+
+def _pair_timing(
+    events: list[dict[str, object]],
+    name: str,
+    start_type: str,
+    end_type: str,
+) -> dict[str, object] | None:
+    start = next((event for event in events if event.get("type") == start_type), None)
+    if start is None:
+        return None
+    end = next(
+        (event for event in events if event.get("type") == end_type and int(event["offset_ms"]) >= int(start["offset_ms"])),
+        None,
+    )
+    if end is None:
+        return None
+    return _timing_record(name, start, end)
+
+
+def _repeated_pair_timings(
+    events: list[dict[str, object]],
+    name: str,
+    start_type: str,
+    end_type: str,
+) -> list[dict[str, object]]:
+    timings: list[dict[str, object]] = []
+    pending: dict[str, object] | None = None
+    segment_index = 1
+    for event in events:
+        if event.get("type") == start_type:
+            pending = event
+            continue
+        if pending is not None and event.get("type") == end_type:
+            timing = _timing_record(name, pending, event)
+            timing["segment_index"] = segment_index
+            timings.append(timing)
+            segment_index += 1
+            pending = None
+    return timings
+
+
+def _timing_record(name: str, start: dict[str, object], end: dict[str, object]) -> dict[str, object]:
+    return {
+        "turn": start.get("turn"),
+        "name": name,
+        "started_at": start.get("at"),
+        "finished_at": end.get("at"),
+        "start_offset_ms": start.get("offset_ms"),
+        "end_offset_ms": end.get("offset_ms"),
+        "duration_ms": int(end["offset_ms"]) - int(start["offset_ms"]),
+        "start_event": start.get("type"),
+        "end_event": end.get("type"),
+    }