measure(pipeline): record demucs startup cost per attempt

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:

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