rbrooks/Quest-Board

Watch

Fork 0

[CI][Performance] The synthetic session harness spends ~17 minutes spawning ffmpeg one span at a time #684

New issue

Closed

opened 2026-09-17 20:10:43 +00:00 by claude-bot · 2 comments

claude-bot commented

2026-09-17 20:10:43 +00:00

Collaborator

Investigated after the job started taking 20–30 minutes per run and became the long pole on every PR. Read-only; nothing changed.

Where the time actually goes

From run #9846, job synthetic-session:

Step	Tests	Time
Manifest, scene and scorers	74	1m 23s
Assembly, fingerprints, golden transcripts	21	7m 42s
Guards and negative fixtures	10	17m 29s
Harness self-check	—	6s
Stub eval leg	—	4s

Ten tests, 17½ minutes — about 105 seconds each. The other 95 tests together take under 10.

Why

tests/test_synthetic_session_guards.py has 10 tests, 7 of which call _transcribe(...) with VAD enabled (none pass vad=False). That goes through transcribe_session_vad, and for each track it does:

one _run_silencedetect — an ffmpeg process scanning the whole track (audio_service.py:1066, :1357)
up to _LANGUAGE_DETECT_ATTEMPTS = 3 ffmpeg cuts for language probing (:1177-1181)
one _cut_segment ffmpeg process per speech span, sequentially (:1441-1445)

The fixture scene is 1,800 s (30 minutes), 5 speaker tracks, 218 utterances. Computing the spans from manifest.json with the configured min_silence_ms=2000 and _VAD_PADDING_MS=300, almost nothing merges — the scripted gaps are mostly longer than 2 s:

astrid  46 utterances ->  45 spans
bryn    43 utterances ->  42 spans
corvin  40 utterances ->  38 spans
nix     71 utterances ->  69 spans
wren    18 utterances ->  18 spans
                TOTAL -> 212 spans

So one VAD transcribe ≈ 5 + 15 + 212 = 232 ffmpeg process spawns, serial. Seven tests doing that is roughly 1,600 ffmpeg spawns for one test file — ~0.65 s each against the measured 1,049 s, which is about right for process start plus a WAV write.

It is not decode cost: _cut_segment puts -ss before -i (:1093-1102), so each cut is an input seek, not a scan. The bill is process startup, paid 232 times per call.

This is not only a CI problem

The same path runs on every real session with VAD on. A 3-hour session with five speakers is roughly 6× the spans — on the order of 1,300 sequential ffmpeg spawns inside the Celery worker, ~10 minutes of pure process overhead before any transcription happens. In production the ASR call dominates, so it is less visible; it is still ten minutes of nothing.

Suggested shape, cheapest first

Run the guard tests in parallel. They are independent and use tmp_path_factory, so pytest -n auto (xdist) should divide the 17½ minutes by the runner's core count. CI-only, no production risk, smallest diff. Do this first.
Batch the cuts per track into one ffmpeg invocation. ffmpeg takes many outputs in a single command (-ss A1 -t D1 out1.wav -ss A2 -t D2 out2.wav …), or the segment muxer with -segment_times emits every boundary in one pass and the silent pieces get discarded. That turns 212 spawns into 5. This is the real fix and it helps production, not just CI — worth its own change with a before/after measurement.
Cache silencedetect per track in the harness support layer. clean_session is module-scoped and most guards mutate one track, so the other four are rescanned identically each time. Keyed on (path, size, mtime, noise floor, min silence). Only helps the tests.

Not suggested: shortening the scene for the guards. They exist to watch each guard fire on real audio (#432, #433), and a shorter scene changes what is being exercised.

Caveats

The per-spawn cost is derived from the measured step time divided by the computed spawn count, not from instrumenting ffmpeg directly. The span arithmetic is computed from the manifest rather than read from a run, so merging under real silencedetect output may differ a little — the order of magnitude is not in doubt.

Found while asking why CI runs had grown to 20–30 minutes (#659 lane work).

Investigated after the job started taking 20–30 minutes per run and became the long pole on every PR. **Read-only; nothing changed.** ## Where the time actually goes From run [#9846](https://git.rhoving.com/rbrooks/Quest-Board/actions/runs/1149), job `synthetic-session`: | Step | Tests | Time | |---|---:|---:| | Manifest, scene and scorers | 74 | 1m 23s | | Assembly, fingerprints, golden transcripts | 21 | 7m 42s | | **Guards and negative fixtures** | **10** | **17m 29s** | | Harness self-check | — | 6s | | Stub eval leg | — | 4s | **Ten tests, 17½ minutes — about 105 seconds each.** The other 95 tests together take under 10. ## Why `tests/test_synthetic_session_guards.py` has 10 tests, **7 of which call `_transcribe(...)` with VAD enabled** (none pass `vad=False`). That goes through `transcribe_session_vad`, and for each track it does: 1. one `_run_silencedetect` — an ffmpeg process scanning the **whole** track (`audio_service.py:1066`, `:1357`) 2. up to `_LANGUAGE_DETECT_ATTEMPTS` = 3 ffmpeg cuts for language probing (`:1177-1181`) 3. **one `_cut_segment` ffmpeg process per speech span**, sequentially (`:1441-1445`) The fixture scene is **1,800 s (30 minutes), 5 speaker tracks, 218 utterances**. Computing the spans from `manifest.json` with the configured `min_silence_ms=2000` and `_VAD_PADDING_MS=300`, almost nothing merges — the scripted gaps are mostly longer than 2 s: ``` astrid 46 utterances -> 45 spans bryn 43 utterances -> 42 spans corvin 40 utterances -> 38 spans nix 71 utterances -> 69 spans wren 18 utterances -> 18 spans TOTAL -> 212 spans ``` So **one VAD transcribe ≈ 5 + 15 + 212 = 232 ffmpeg process spawns**, serial. Seven tests doing that is **roughly 1,600 ffmpeg spawns** for one test file — ~0.65 s each against the measured 1,049 s, which is about right for process start plus a WAV write. It is **not** decode cost: `_cut_segment` puts `-ss` *before* `-i` (`:1093-1102`), so each cut is an input seek, not a scan. The bill is process startup, paid 232 times per call. ## This is not only a CI problem The same path runs on every real session with VAD on. A 3-hour session with five speakers is roughly 6× the spans — on the order of **1,300 sequential ffmpeg spawns inside the Celery worker**, ~10 minutes of pure process overhead before any transcription happens. In production the ASR call dominates, so it is less visible; it is still ten minutes of nothing. ## Suggested shape, cheapest first 1. **Run the guard tests in parallel.** They are independent and use `tmp_path_factory`, so `pytest -n auto` (xdist) should divide the 17½ minutes by the runner's core count. CI-only, no production risk, smallest diff. Do this first. 2. **Batch the cuts per track into one ffmpeg invocation.** ffmpeg takes many outputs in a single command (`-ss A1 -t D1 out1.wav -ss A2 -t D2 out2.wav …`), or the `segment` muxer with `-segment_times` emits every boundary in one pass and the silent pieces get discarded. That turns 212 spawns into 5. **This is the real fix and it helps production, not just CI** — worth its own change with a before/after measurement. 3. **Cache `silencedetect` per track in the harness support layer.** `clean_session` is module-scoped and most guards mutate one track, so the other four are rescanned identically each time. Keyed on (path, size, mtime, noise floor, min silence). Only helps the tests. Not suggested: shortening the scene for the guards. They exist to watch each guard fire on real audio (#432, #433), and a shorter scene changes what is being exercised. ## Caveats The per-spawn cost is derived from the measured step time divided by the computed spawn count, not from instrumenting ffmpeg directly. The span arithmetic is computed from the manifest rather than read from a run, so merging under real `silencedetect` output may differ a little — the order of magnitude is not in doubt. Found while asking why CI runs had grown to 20–30 minutes (#659 lane work).

claude-bot commented

2026-09-17 20:20:39 +00:00

Author

Collaborator

Correction to suggestion 2 — the batching form I proposed would make production slower

Reading the code properly after filing this. Two corrections, one of them important.

The multi-output form in the issue body is wrong. Today _cut_segment puts -ss before -i (audio_service.py:1093-1102), which is an input seek — ffmpeg jumps to the offset without decoding. In a multi-output command:

ffmpeg -i in.wav -ss A1 -t D1 out1.wav -ss A2 -t D2 out2.wav …

those -ss flags are now output options, which decode from zero and discard for every output. On a 3-hour track with ~1,300 spans that is decoding three hours thirteen hundred times. It would be a severe regression, not an optimisation.

The workable form is the segment muxer (-f segment -segment_times …): one sequential decode pass that emits every boundary, after which the silent pieces are discarded. Quality-neutral on this path because the bot writes 16 kHz mono PCM, where every sample is a frame, so cut boundaries stay sample-exact and window.keeps() sees the spans it sees today. It would not be safe on a compressed input — which never reaches this path, but is worth writing down before someone changes the capture format.

Also: _FFMPEG_TIMEOUT = 600 is currently per cut. Batched, a single invocation has to complete every cut inside it, and tripping it loses a whole track rather than one span. That has to be reworked deliberately, not inherited.

And one thing I overstated

I implied per-span failure isolation was at risk. It is not. _transcribe_span_resiliently isolates the ASR call, not the cut, and batching leaves the span loop, the skipped accounting and the _SPAN_MAX_FAILURE_SHARE guard exactly as they are. _cut_segment is not wrapped in a try today either, so a cut failure is already all-or-nothing for the run.

That resilience exists because of a production incident and is worth not disturbing — the docstring records it: "three clips of 77 on one track of six returned 500 deterministically… left a 3-hour recording with nothing to show for it."

Net

Suggestion 2 is still worth doing and still helps production — but as a segment-muxer change with a reworked timeout and before/after timings, not as the one-line multi-output swap this issue first described.

Suggestion 3 has a condition too: the guards mutate audio in place (zero_after, zero_tail), so a silencedetect cache keyed on size+mtime could serve stale data and let a guard pass without its mutation being seen — the exact failure mode that file's docstring says this repo keeps hitting. Key it on a content hash or leave it alone.

Doing suggestion 1 now, which touches no production code.

## Correction to suggestion 2 — the batching form I proposed would make production *slower* Reading the code properly after filing this. Two corrections, one of them important. **The multi-output form in the issue body is wrong.** Today `_cut_segment` puts `-ss` **before** `-i` (`audio_service.py:1093-1102`), which is an *input* seek — ffmpeg jumps to the offset without decoding. In a multi-output command: ``` ffmpeg -i in.wav -ss A1 -t D1 out1.wav -ss A2 -t D2 out2.wav … ``` those `-ss` flags are now *output* options, which decode from zero and discard for every output. On a 3-hour track with ~1,300 spans that is decoding three hours thirteen hundred times. It would be a severe regression, not an optimisation. **The workable form is the `segment` muxer** (`-f segment -segment_times …`): one sequential decode pass that emits every boundary, after which the silent pieces are discarded. Quality-neutral on this path because the bot writes 16 kHz mono PCM, where every sample is a frame, so cut boundaries stay sample-exact and `window.keeps()` sees the spans it sees today. It would *not* be safe on a compressed input — which never reaches this path, but is worth writing down before someone changes the capture format. **Also: `_FFMPEG_TIMEOUT = 600` is currently per cut.** Batched, a single invocation has to complete every cut inside it, and tripping it loses a whole track rather than one span. That has to be reworked deliberately, not inherited. ## And one thing I overstated I implied per-span failure isolation was at risk. It is not. `_transcribe_span_resiliently` isolates the **ASR call**, not the cut, and batching leaves the span loop, the `skipped` accounting and the `_SPAN_MAX_FAILURE_SHARE` guard exactly as they are. `_cut_segment` is not wrapped in a `try` today either, so a cut failure is *already* all-or-nothing for the run. That resilience exists because of a production incident and is worth not disturbing — the docstring records it: *"three clips of 77 on one track of six returned 500 deterministically… left a 3-hour recording with nothing to show for it."* ## Net Suggestion 2 is still worth doing and still helps production — but as a `segment`-muxer change with a reworked timeout and before/after timings, not as the one-line multi-output swap this issue first described. Suggestion 3 has a condition too: the guards mutate audio **in place** (`zero_after`, `zero_tail`), so a silencedetect cache keyed on size+mtime could serve stale data and let a guard pass without its mutation being seen — the exact failure mode that file's docstring says this repo keeps hitting. Key it on a content hash or leave it alone. **Doing suggestion 1 now**, which touches no production code.

rbrooks referenced this issue from a commit

2026-09-17 20:56:10 +00:00

perf(ci): stop the harness guards sleeping through the retry backoff (#684)

claude-bot referenced this issue

2026-09-17 20:56:25 +00:00

Stop the harness guards sleeping through the retry backoff (#684) #685

rbrooks referenced this issue from a commit

2026-09-17 21:23:04 +00:00

Merge PR #685: stop the harness guards sleeping through the retry backoff (#684)

rbrooks referenced this issue from a commit

2026-09-18 01:04:45 +00:00

test(frontend): 30s for the two tests that render 250 entries (#684)

rbrooks referenced this issue from a commit

2026-09-18 01:24:04 +00:00

Merge PR #687: D30 is settled, and 30s for two tests that render 250 entries (#659, #684)

claude-bot referenced this issue

2026-09-29 16:41:26 +00:00

Backend test suite: stop tests waiting on the real network, block unmocked network access, and move the synthetic harness out of the default run #937

claude-bot referenced this issue

2026-09-29 17:16:25 +00:00

test(repo): halve the backend suite, block unmocked network in tests (#937) #938

rbrooks referenced this issue from a commit

2026-10-02 02:55:47 +00:00

Cut a track's speech spans fifty to an ffmpeg process, not one each (#684)

rbrooks referenced this issue from a commit

2026-10-02 02:55:47 +00:00

The batched cut's fallback, against real ffmpeg (#684)

rbrooks referenced this issue from a commit

2026-10-02 03:04:22 +00:00

Cut spans twenty-five to a process, not fifty: the worker's memory (#684)

claude-bot referenced this issue from a pull request that will close it,

2026-10-02 03:22:53 +00:00

Transcription cuts a speaker's phrases twenty-five at a time, not one ffmpeg process each (#684) #1027

claude-bot referenced this issue from a commit

2026-10-02 20:58:13 +00:00

Merge PR #1027: transcription cuts a speaker's phrases twenty-five at a time, not one ffmpeg process each (#684)

claude-bot closed this issue

2026-10-02 20:58:13 +00:00

claude-bot commented

2026-10-02 20:58:20 +00:00

Author

Collaborator

transcribe_session_vad now cuts up to 25 speech spans per ffmpeg run, one input per span, instead of one process per span. The batch size is set by the worker's memory (#841), not speed, and a test pins it with the reason. A failed batch falls back to the unchanged one-at-a-time _cut_segment, so bad audio fails as it did before. Measurements and the rejected single-input form are in the PR body.

Done in PR #1027, merged to main on 2026-10-02 after its CI re-run went green (the one red job on the first run was an end-to-end journeys job, outside this change; the synthetic session harness passed on the branch). `transcribe_session_vad` now cuts up to 25 speech spans per ffmpeg run, one input per span, instead of one process per span. The batch size is set by the worker's memory (#841), not speed, and a test pins it with the reason. A failed batch falls back to the unchanged one-at-a-time `_cut_segment`, so bad audio fails as it did before. Measurements and the rejected single-input form are in the PR body.