perf(video): 优化视频处理性能监控和音频播放

- 添加视频处理性能计时和统计功能 - 实现帧处理时间监控和慢帧警告 - 添加音频文件静音修剪功能 - 优化Windows平台音频播放实现 - 调整默认日志输出频率减少冗余信息 - 修复MediaPipe GPU委托在Windows上的兼容性问题
2026-06-15 23:13:36 +08:00
parent 6dee2a2ff3
commit 08b6543b79
8 changed files with 387 additions and 48 deletions
@@ -1,6 +1,7 @@
 from __future__ import annotations

 import asyncio
+import time

 import cv2
 from aiortc.mediastreams import MediaStreamError
@@ -25,6 +26,39 @@ def _format_pose_debug(pose_result) -> str:
        f"ll={metrics.left_leg_extended}, rl={metrics.right_leg_extended})"
    )

+
+def _new_perf_window() -> dict:
+    return {
+        "frames": 0,
+        "processed": 0,
+        "loop_ms": 0.0,
+        "to_ndarray_ms": 0.0,
+        "detect_ms": 0.0,
+        "show_ms": 0.0,
+        "max_loop_ms": 0.0,
+        "max_detect_ms": 0.0,
+        "detector": {},
+    }
+
+
+def _add_detector_timing(perf: dict, timing: dict[str, float | bool]) -> None:
+    detector = perf["detector"]
+    for key, value in timing.items():
+        if key == "submitted":
+            detector[key] = detector.get(key, 0) + (1 if value else 0)
+            continue
+        value = float(value)
+        detector[key] = detector.get(key, 0.0) + value
+        max_key = f"max_{key}"
+        detector[max_key] = max(detector.get(max_key, 0.0), value)
+
+
+def _avg(perf: dict, key: str, denominator: int) -> float:
+    if denominator <= 0:
+        return 0.0
+    return perf.get(key, 0.0) / denominator
+
+
 class VideoReceiver:
    """视频轨道接收与运动检测流水线"""

@@ -34,10 +68,19 @@ class VideoReceiver:
    async def run(self) -> None:
        """持续接收视频帧并进行姿态检测、渲染和语音播报"""
        log_every_n_frames = max(1, config.video.log_every_n_frames)
+        perf_log_every_n_frames = max(1, config.video.perf_log_every_n_frames)
+        slow_frame_ms = max(0.0, config.video.slow_frame_ms)
        logger.info(
-            "Start receiving video frames, process_every_n={}, log_every_n={}",
+            "Start receiving video frames, process_every_n={}, log_every_n={}, perf_log_every_n={}, slow_frame_ms={}",
            config.video.process_every_n_frames,
            log_every_n_frames,
+            perf_log_every_n_frames,
+            slow_frame_ms,
+        )
+        logger.info(
+            "OpenCV OpenCL status: have_opencl={}, use_opencl={}",
+            cv2.ocl.haveOpenCL(),
+            cv2.ocl.useOpenCL(),
        )

        frame_count = 0
@@ -57,23 +100,43 @@ class VideoReceiver:
        last_announced_rep = 0
        last_pose_result = None
        last_annotated = None
+        perf = _new_perf_window()

        try:
            while True:
+                loop_started = time.perf_counter()
                frame = await self._track.recv()
                frame_count += 1
+                recv_done = time.perf_counter()
                raw_img = frame.to_ndarray(format="bgr24")
+                ndarray_done = time.perf_counter()
                timestamp_ms = int(frame.time * 1000) if frame.time is not None else frame_count * 33

+                detect_ms = 0.0
                if frame_count % config.video.process_every_n_frames == 0 or last_pose_result is None:
+                    detect_started = time.perf_counter()
                    processed_count += 1
                    last_annotated, last_pose_result = detector.process_frame(raw_img, timestamp_ms)
+                    detect_ms = (time.perf_counter() - detect_started) * 1000
+                    perf["processed"] += 1
+                    perf["detect_ms"] += detect_ms
+                    perf["max_detect_ms"] = max(perf["max_detect_ms"], detect_ms)
+                    _add_detector_timing(perf, detector.last_timing)
                    if last_pose_result.rep_count > last_announced_rep:
                        last_announced_rep = last_pose_result.rep_count
+                        announce_started = time.perf_counter()
                        announcer.announce_count(last_announced_rep)
+                        logger.info(
+                            "Rep completed and audio requested: count={}, frame={}, announce_call_ms={:.1f}",
+                            last_announced_rep,
+                            frame_count,
+                            (time.perf_counter() - announce_started) * 1000,
+                        )

                display_img = last_annotated if last_annotated is not None else raw_img
+                show_started = time.perf_counter()
                show_frame(display_img)
+                show_done = time.perf_counter()

                if frame_count % log_every_n_frames == 0:
                    logger.info(
@@ -87,6 +150,53 @@ class VideoReceiver:
                        _format_pose_debug(last_pose_result) if last_pose_result is not None else "metrics=None",
                    )

+                loop_ms = (show_done - loop_started) * 1000
+                to_ndarray_ms = (ndarray_done - recv_done) * 1000
+                show_ms = (show_done - show_started) * 1000
+                perf["frames"] += 1
+                perf["loop_ms"] += loop_ms
+                perf["to_ndarray_ms"] += to_ndarray_ms
+                perf["show_ms"] += show_ms
+                perf["max_loop_ms"] = max(perf["max_loop_ms"], loop_ms)
+
+                if slow_frame_ms and loop_ms >= slow_frame_ms:
+                    logger.warning(
+                        "Slow video frame: frame={}, loop_ms={:.1f}, detect_ms={:.1f}, to_ndarray_ms={:.1f}, show_ms={:.1f}, shape={}",
+                        frame_count,
+                        loop_ms,
+                        detect_ms,
+                        to_ndarray_ms,
+                        show_ms,
+                        raw_img.shape,
+                    )
+
+                if frame_count % perf_log_every_n_frames == 0:
+                    frames = perf["frames"]
+                    processed = perf["processed"]
+                    detector_perf = perf["detector"]
+                    logger.info(
+                        "Perf window: frames={}, processed={}, avg_loop_ms={:.1f}, max_loop_ms={:.1f}, avg_to_ndarray_ms={:.1f}, "
+                        "avg_detect_ms={:.1f}, max_detect_ms={:.1f}, avg_show_ms={:.1f}, detector_avg_total_ms={:.1f}, "
+                        "detector_max_total_ms={:.1f}, detector_avg_wait_ms={:.1f}, detector_max_wait_ms={:.1f}, "
+                        "detector_avg_convert_ms={:.1f}, detector_avg_postprocess_draw_ms={:.1f}, detector_submitted={}",
+                        frames,
+                        processed,
+                        _avg(perf, "loop_ms", frames),
+                        perf["max_loop_ms"],
+                        _avg(perf, "to_ndarray_ms", frames),
+                        _avg(perf, "detect_ms", processed),
+                        perf["max_detect_ms"],
+                        _avg(perf, "show_ms", frames),
+                        _avg(detector_perf, "total_ms", processed),
+                        detector_perf.get("max_total_ms", 0.0),
+                        _avg(detector_perf, "wait_ms", processed),
+                        detector_perf.get("max_wait_ms", 0.0),
+                        _avg(detector_perf, "convert_ms", processed),
+                        _avg(detector_perf, "postprocess_draw_ms", processed),
+                        detector_perf.get("submitted", 0),
+                    )
+                    perf = _new_perf_window()
+
                if is_esc_pressed():
                    logger.info("ESC pressed, closing display")
                    break