diff --git a/app/pipeline/separate.py b/app/pipeline/separate.py index 58864b6..2b72390 100644 --- a/app/pipeline/separate.py +++ b/app/pipeline/separate.py @@ -55,6 +55,7 @@ def _run_demucs(job: Job, source: Path, job_dir: Path, device: str) -> tuple[int except ModuleNotFoundError: pass + spawn_at = time.monotonic() proc = subprocess.Popen( _demucs_cmd(device, source, job_dir), stdout=subprocess.DEVNULL, @@ -66,6 +67,11 @@ def _run_demucs(job: Job, source: Path, job_dir: Path, device: str) -> tuple[int if proc.stderr is None: raise RuntimeError("demucs subprocess has no stderr pipe") set_proc(job.id, proc) + # Time from spawn to demucs's first progress line -- process/model-load + # startup cost, as opposed to actual separation work (#288). Measurement + # only: subprocess isolation (kill-on-cancel, crash containment) is a + # design feature we keep regardless of what this turns out to be. + startup_recorded = False # tqdm uses \r to redraw -- read char-by-char and split on \r or \n. # Keep the last few non-progress lines so we can surface them if demucs @@ -105,6 +111,13 @@ def _watchdog() -> None: continue m = _PCT_RE.search(line) if m: + if not startup_recorded: + startup_recorded = True + if job.stage_timings is None: + job.stage_timings = {} + job.stage_timings["separate_startup"] = round( + time.monotonic() - spawn_at, 1 + ) pct = max(0, min(100, int(m.group(1)))) _set(job, progress=pct / 100.0, stage=f"Separating {pct}%") else: diff --git a/tests/test_separate_fallback.py b/tests/test_separate_fallback.py index b90348b..c3fa58c 100644 --- a/tests/test_separate_fallback.py +++ b/tests/test_separate_fallback.py @@ -70,6 +70,21 @@ def test_gpu_failure_falls_back_to_cpu(job, tmp_path, monkeypatch, caplog): assert "CUDA out of memory" in warning +def test_records_startup_timing_on_first_progress_line(job, tmp_path, monkeypatch): + """#288: measurement only -- time from Popen to the first progress line + demucs emits, so the real subprocess/model-load startup cost can be + quantified before deciding whether it's worth a design change.""" + calls: list[str] = [] + monkeypatch.setattr(sep_mod, "get_demucs_device", lambda: "cpu") + monkeypatch.setattr(sep_mod, "_demucs_cmd", _stub_cmds(set(), calls)) + + sep_mod.separate(job, tmp_path / "source.wav", tmp_path) + + assert job.stage_timings is not None + assert "separate_startup" in job.stage_timings + assert job.stage_timings["separate_startup"] >= 0.0 + + def test_gpu_success_needs_no_fallback(job, tmp_path, monkeypatch): calls: list[str] = [] monkeypatch.setattr(sep_mod, "get_demucs_device", lambda: "cuda")