diff --git a/src/dlna_stream_server/handlers/constants.py b/src/dlna_stream_server/handlers/constants.py index 85f7616..1d99172 100644 --- a/src/dlna_stream_server/handlers/constants.py +++ b/src/dlna_stream_server/handlers/constants.py @@ -128,6 +128,17 @@ "aac": "audio/aac", } +# Диагностика темпа подачи: длина окна замера и пороги скорости +# по кодеку, ниже которых подача считается медленнее реального +# времени (кбит/с). Пороги — с запасом ниже типичных битрейтов: +# FLAC ~1000-1400, MP3 320, радио-AAC ~128 +STREAM_RATE_WINDOW = 30.0 +STREAM_RATE_THRESHOLDS_KBPS = { + "flac": 700, + "mp3": 250, + "aac": 90, +} + # MIME-типы для protocolInfo в DIDL-метаданных привязки Ruark. # Ресурс, объявленный как audio/aac, Ruark качает, но не воспроизводит — # ADTS-поток радио играет только под вывеской audio/mpeg diff --git a/src/dlna_stream_server/handlers/ffmpeg_supervisor.py b/src/dlna_stream_server/handlers/ffmpeg_supervisor.py index 2e80b0f..0d2564f 100644 --- a/src/dlna_stream_server/handlers/ffmpeg_supervisor.py +++ b/src/dlna_stream_server/handlers/ffmpeg_supervisor.py @@ -342,6 +342,7 @@ async def _log_stderr(self, proc: asyncio.subprocess.Process) -> None: "error", "failed", "connection", + "reconnect", "broken", "timeout", "invalid data found", diff --git a/src/dlna_stream_server/handlers/stream_handler.py b/src/dlna_stream_server/handlers/stream_handler.py index 8a74a90..551ba48 100644 --- a/src/dlna_stream_server/handlers/stream_handler.py +++ b/src/dlna_stream_server/handlers/stream_handler.py @@ -19,6 +19,8 @@ FFMPEG_LOCAL_MP3_PARAMS, FFMPEG_MP3_PARAMS, STREAM_MIME_TYPES, + STREAM_RATE_THRESHOLDS_KBPS, + STREAM_RATE_WINDOW, ) from .ffmpeg_supervisor import FfmpegSupervisor @@ -157,6 +159,33 @@ async def start_ffmpeg_stream( await self._ffmpeg.start(yandex_url, params, radio) + def _log_stream_pacing( + self, + window_bytes: int, + elapsed: float, + source_wait: float, + client_wait: float, + ) -> None: + """Логирует темп подачи за окно; ниже реального времени — WARNING. + + Доли ожиданий называют узкое место: источник — CDN/FFmpeg, + клиент — сеть до устройства (Wi-Fi Ruark). + """ + if elapsed <= 0: + return + kbps = window_bytes * 8 / 1000 / elapsed + message = ( + f"📈 Темп подачи: {kbps:.0f} кбит/с за {elapsed:.0f}с " + f"({self._stream_codec}); ожидание источника " + f"{source_wait / elapsed * 100:.0f}%, " + f"ожидание клиента {client_wait / elapsed * 100:.0f}%" + ) + threshold = STREAM_RATE_THRESHOLDS_KBPS.get(self._stream_codec, 0) + if kbps < threshold: + logger.warning(f"⚠️ Подача ниже реального времени! {message}") + else: + logger.debug(message) + async def stream_audio(self, radio: bool = False) -> StreamingResponse: """Отдаёт потоковый аудио-ответ клиенту. @@ -180,6 +209,11 @@ async def generate(): total_bytes_sent = 0 serve_started = time.monotonic() first_chunk_sent = False + # Окно замера темпа подачи и виновника ожиданий + window_started = serve_started + window_bytes = 0 + window_source_wait = 0.0 + window_client_wait = 0.0 while True: if self._client_epoch != client_epoch: logger.info( @@ -195,6 +229,7 @@ async def generate(): ) break + read_started = time.monotonic() try: chunk = await asyncio.wait_for( stdout.read(4096), @@ -235,6 +270,7 @@ async def generate(): f"{time.monotonic() - serve_started:.2f}с " f"после подключения" ) + window_source_wait += time.monotonic() - read_started total_bytes_sent += len(chunk) # Диагностика: логируем прогресс передачи данных if total_bytes_sent % (1024 * 1024) == 0: # Каждый МБ @@ -243,7 +279,23 @@ async def generate(): f"{total_bytes_sent // 1024 // 1024} МБ" ) + send_started = time.monotonic() yield chunk + now = time.monotonic() + window_client_wait += now - send_started + window_bytes += len(chunk) + + if now - window_started >= STREAM_RATE_WINDOW: + self._log_stream_pacing( + window_bytes, + now - window_started, + window_source_wait, + window_client_wait, + ) + window_started = now + window_bytes = 0 + window_source_wait = 0.0 + window_client_wait = 0.0 # После выхода из цикла логируем завершение FFmpeg if proc.returncode is not None: diff --git a/tests/test_stream_handler.py b/tests/test_stream_handler.py index 28b694e..6fe9db0 100644 --- a/tests/test_stream_handler.py +++ b/tests/test_stream_handler.py @@ -1,4 +1,5 @@ import asyncio +import logging import time from unittest.mock import AsyncMock @@ -193,6 +194,40 @@ async def test_new_client_displaces_previous_stream(): await handler.stop_ffmpeg() +def test_slow_flac_pacing_logged_as_warning(caplog): + """FLAC на ~320 кбит/с — втрое ниже реального времени, WARNING.""" + handler, _ = make_handler() + handler._stream_codec = "flac" + + with caplog.at_level(logging.WARNING): + handler._log_stream_pacing( + window_bytes=1_200_000, + elapsed=30.0, + source_wait=25.0, + client_wait=1.0, + ) + + assert any( + "ниже реального времени" in record.message for record in caplog.records + ) + + +def test_healthy_mp3_pacing_stays_quiet(caplog): + """Тот же темп ~320 кбит/с для MP3 — норма, без WARNING.""" + handler, _ = make_handler() + handler._stream_codec = "mp3" + + with caplog.at_level(logging.WARNING): + handler._log_stream_pacing( + window_bytes=1_200_000, + elapsed=30.0, + source_wait=0.5, + client_wait=28.0, + ) + + assert not caplog.records + + async def test_radio_declared_as_mpeg_in_didl(fast_sleep): """Радио: Content-Type остаётся aac, но в DIDL — audio/mpeg.