Split HLS cold-start startup phase into spawn / input-open+probe / first-GOP #472

New Issue

2026-07-19T20:33:30+02:00

timothy commented

2026-07-19 20:33:30 +02:00

Follow-up to #350, scoped by its measurement (36 cold-starts on prod 26.10.0, N=33 content samples — see that comment).

Why

The #446 instrumentation split cold-start into setup + startup + fill. The data says:

phase	median	max	variance
`setup`	~160ms	612ms	~none
`startup`	1579ms	8127ms	all of it
`fill`	200ms	211ms	~none

startup is 81% of total and carries 100% of the variance, but it is a single opaque bucket spanning FFmpeg process spawn → input open/probe → decoder/encoder init → first GOP → live.m3u8 appears.

Crucially, the same channel varies up to 7.2× across repeat tunes with an identical filter graph (ch120 [3601, 500], ch124 [3516, 3534, 601], ch125 [8127, 6116, 1579]). So the driver is per-tune, not per-profile — which already falsified all three optimizations #350 had planned (see that comment). Two candidates remain and they need opposite fixes:

input open/probe over the NFS mount (large .mkv, cold page cache, network stall) → fix is probe/analyzeduration tuning, prefetch, or caching
VAAPI encoder init under GPU contention (Frigate shares renderD128) → fix is scheduling/priority or device selection

Guessing between them is what produced #350's wrong hypothesis ranking the first time. Measure, then optimize.

Scope

Extend the existing HLS cold-start structured log with a sub-split of startup. Suggested boundaries:

spawnMs — Process.Start → first FFmpeg progress/stderr activity
inputOpenMs — → input opened / probe complete (parse FFmpeg's own -progress/stderr milestones, or bracket with -loglevel markers)
firstGopMs — → live.m3u8 exists

Keep it Information-level, new-session path only, same one-line-per-cold-start shape. No new endpoint, no config knob, no transcode behavior change — consistent with #446.

Note the exact boundaries may need to follow what FFmpeg actually reports; if a clean three-way split isn't achievable from the process output, a two-way spawn+open vs firstGop split still discriminates the two hypotheses and is acceptable.

Done-when

Pre-merge (this issue):

startup sub-split emitted in the cold-start log line
Pure/parsing logic unit-tested (follow ColdStartFeaturesTests precedent)
Local build + full test pass green
CI green
Adversarial review passed

Post-release (tracked on #350, not a merge gate — see note below):

Fresh samples collected on prod and posted to #350 identifying the dominant sub-phase

Why the split (2026-07-19): the original checklist put "collect fresh prod samples" in the same list as the pre-merge criteria, which encodes a circular dependency — prod can only run this code after the PR merges and a release ships, so the box could never be ticked before merge, and the merge-consent gate would deny forever. The measurement is still required; it just belongs to #350 (the parent that consumes the data) rather than to this issue's merge gate. Any future instrumentation issue should split its checklist the same way.

Notes

Log-only change; no API/SPA surface → no OpenAPI/doc regen expected.
priority: medium, matching #350.

Follow-up to #350, scoped by its measurement (36 cold-starts on prod 26.10.0, N=33 content samples — see [that comment](http://192.168.1.95:3000/timothy/ersatztv/issues/350#issuecomment-13474)). ## Why The #446 instrumentation split cold-start into `setup + startup + fill`. The data says: | phase | median | max | variance | |---|---|---|---| | `setup` | ~160ms | 612ms | ~none | | **`startup`** | **1579ms** | **8127ms** | **all of it** | | `fill` | 200ms | 211ms | ~none | `startup` is **81% of total and carries 100% of the variance**, but it is a single opaque bucket spanning FFmpeg process spawn → input open/probe → decoder/encoder init → first GOP → `live.m3u8` appears. Crucially, **the same channel varies up to 7.2× across repeat tunes** with an identical filter graph (ch120 `[3601, 500]`, ch124 `[3516, 3534, 601]`, ch125 `[8127, 6116, 1579]`). So the driver is per-tune, not per-profile — which already falsified all three optimizations #350 had planned (see that comment). Two candidates remain and they need **opposite** fixes: - **input open/probe** over the NFS mount (large `.mkv`, cold page cache, network stall) → fix is probe/analyzeduration tuning, prefetch, or caching - **VAAPI encoder init under GPU contention** (Frigate shares `renderD128`) → fix is scheduling/priority or device selection Guessing between them is what produced #350's wrong hypothesis ranking the first time. Measure, then optimize. ## Scope Extend the existing `HLS cold-start` structured log with a sub-split of `startup`. Suggested boundaries: - `spawnMs` — `Process.Start` → first FFmpeg progress/stderr activity - `inputOpenMs` — → input opened / probe complete (parse FFmpeg's own `-progress`/stderr milestones, or bracket with `-loglevel` markers) - `firstGopMs` — → `live.m3u8` exists Keep it Information-level, new-session path only, same one-line-per-cold-start shape. No new endpoint, no config knob, no transcode behavior change — consistent with #446. Note the exact boundaries may need to follow what FFmpeg actually reports; if a clean three-way split isn't achievable from the process output, a two-way `spawn+open` vs `firstGop` split still discriminates the two hypotheses and is acceptable. ## Done-when Pre-merge (this issue): - [x] `startup` sub-split emitted in the cold-start log line - [x] Pure/parsing logic unit-tested (follow `ColdStartFeaturesTests` precedent) - [x] Local build + full test pass green - [x] CI green - [x] Adversarial review passed Post-release (tracked on #350, **not** a merge gate — see note below): - Fresh samples collected on prod and posted to #350 identifying the dominant sub-phase > **Why the split (2026-07-19):** the original checklist put "collect fresh prod samples" in the same list as the pre-merge criteria, which encodes a circular dependency — prod can only run this code *after* the PR merges and a release ships, so the box could never be ticked before merge, and the merge-consent gate would deny forever. The measurement is still required; it just belongs to #350 (the parent that consumes the data) rather than to this issue's merge gate. Any future instrumentation issue should split its checklist the same way. ## Notes - Log-only change; no API/SPA surface → no OpenAPI/doc regen expected. - `priority: medium`, matching #350.

timothy added the enhancement priority: medium labels 2026-07-19 20:33:30 +02:00

timothy referenced this issue

2026-07-19 20:36:26 +02:00

Channel cold-start ~7s to first segment — slow tune-in via Dispatcharr/Kodi (heavy transcode profile) #350

timothy referenced this issue

2026-07-19 20:36:48 +02:00

ChicoryTV rewrite — queue tracker (goal, arc, session protocol) #237

timothy referenced this issue

2026-07-19 22:20:47 +02:00

ChicoryTV rewrite — queue tracker (goal, arc, session protocol) #237

timothy added the in-progress label 2026-07-19 22:33:05 +02:00

timothy commented

2026-07-19 22:33:11 +02:00

Claiming (Claude Code orchestrator session, 2026-07-19).

Selected via the deterministic selector (scripts/select-queue.sh) — top of the priority: medium tier was #350, but its own wrap comment names this issue as "the actual next step", so #350 is the parent/container and #472 is the pickup. Unclaimed, deps clear, no prior comments.

Plan, in the spirit of the lesson #350 taught: instrument first, don't guess. I'll extend the #446 HLS cold-start line with a startup sub-split, keeping the exact boundaries honest to what FFmpeg actually reports — if a clean three-way split isn't derivable from the process output, I'll ship the two-way spawn+open vs firstGop split the issue explicitly accepts, and say so rather than inventing a boundary the data can't support. Parsing logic gets pure unit tests per the ColdStartFeaturesTests precedent.

Prod sampling (last Done-when box) happens after the release reaches prod; if that isn't possible this session I'll leave that box unticked rather than tick it on a local run.

Claiming (Claude Code orchestrator session, 2026-07-19). Selected via the deterministic selector (`scripts/select-queue.sh`) — top of the `priority: medium` tier was #350, but its own wrap comment names **this issue** as "the actual next step", so #350 is the parent/container and #472 is the pickup. Unclaimed, deps clear, no prior comments. Plan, in the spirit of the lesson #350 taught: instrument first, don't guess. I'll extend the #446 `HLS cold-start` line with a `startup` sub-split, keeping the exact boundaries honest to what FFmpeg actually reports — if a clean three-way split isn't derivable from the process output, I'll ship the two-way `spawn+open` vs `firstGop` split the issue explicitly accepts, and say so rather than inventing a boundary the data can't support. Parsing logic gets pure unit tests per the `ColdStartFeaturesTests` precedent. Prod sampling (last Done-when box) happens after the release reaches prod; if that isn't possible this session I'll leave that box unticked rather than tick it on a local run.

timothy referenced this issue from a commit

2026-07-19 23:05:22 +02:00

feat(472): sub-split the HLS cold-start startup phase

timothy referenced a pull request that will close this issue

2026-07-19 23:05:43 +02:00

feat(472): sub-split the HLS cold-start startup phase #482

timothy referenced this issue

2026-07-19 23:07:55 +02:00

Scanner has no anti-nuke guard: a successful-but-empty media-server fetch flags an entire library FileNotFound #477

timothy referenced this issue

2026-07-19 23:54:42 +02:00

ChicoryTV rewrite — queue tracker (goal, arc, session protocol) #237

timothy closed this issue

2026-07-19 23:59:23 +02:00

timothy commented

2026-07-20 00:00:21 +02:00

Closed — shipped in PR #482 (merged, CI green @ `37674d65`)

What landed

The HLS cold-start line now sub-splits startup:

startup split ThreeWay spans runEntry (prep 143ms + ffmpegInit 1290ms + firstGop 146ms)

prep — ErsatzTV-side work before FFmpeg exists (playout-item resolution, pipeline build, graphics-engine spawn)
ffmpegInit — FFmpeg launch → its first -progress output
firstGop — → live.m3u8 exists

Log-only: no transcode behavior change, no endpoint, no config knob. No API/SPA surface, so no doc or OpenAPI regen was owed.

Read this before interpreting the data — the split does NOT resolve this issue's headline question

The pipeline runs -loglevel error -nostats -hide_banner, so a healthy FFmpeg writes nothing to stderr. Input-open/probe therefore cannot be separated from encoder-init without changing the FFmpeg command — which this instrumentation must not do. -progress on stdout is the only zero-cost milestone available, so ffmpegInit still contains BOTH rival hypotheses (NFS input open and VAAPI init under contention).

What is genuinely new is the ErsatzTV-prep vs FFmpeg-time boundary. The issue explicitly accepted a two-way outcome, so this is in scope — but if prod samples show ffmpegInit dominating (likely), the NFS-vs-VAAPI question is still open and needs a different instrument, or a deliberately-justified loglevel change. Do not read a large ffmpegInit as evidence for either hypothesis.

Three caveats, documented on the type rather than left to be rediscovered

The buckets span the worker's Run entry, not the startup stopwatch — so prep + ffmpegInit + firstGop is a superset of startup (prep overlaps the tail of setup). Hence spans runEntry in the log line itself. Do not subtract these from startup.
The playlist is detected by a 100ms poll, so up to 100ms of error lands entirely in firstGop, the smallest bucket — and can flip a sample between ThreeWay and TwoWayLateProgress.
If the session's first FFmpeg process fails and a second produces the playlist, ffmpegInit spans the retry.

Design stance: degrade, never invent

Milestones are recorded on the worker thread and read on the request thread, so ordering is validated, not assumed. Any missing/out-of-order milestone degrades to a coarser splitKind (ThreeWay → TwoWay/TwoWayLateProgress → Unavailable) rather than producing a negative or fabricated bucket. A stale live.m3u8 (possible when the pre-session folder wipe fails — EmptyFolder swallows failures into a warning) is reported Unavailable rather than as a plausible-looking sample. Milestones are set-once via Interlocked, so a long session's repeated Transcode() calls can't overwrite the cold-start numbers.

Files

ColdStartStartupSplit.cs (new, Core/FFmpeg), PlaylistSegmentsResult.cs, HlsSessionWorker.cs, StartFFmpegSessionHandler.cs, ColdStartStartupSplitTests.cs (new, 12 cases).

Review

Four cold-context adversarial passes, each over code the previous hadn't seen; every Medium-or-above fixed, none waived. Full record in the PR comment. Notably, two Mediums were the same defect class this PR exists to prevent — a comment whose rationale didn't match the mechanism — each landed inside the fix for the previous one. One Low is accepted and documented rather than fixed (stated in that comment).

Done-when: reworded, not quietly ticked

The original checklist required prod samples before merge, which is circular — prod only runs this after a release. Split into pre-merge criteria (all met) and a post-release item now owned by #350. Rationale recorded in the issue body so the next instrumentation issue doesn't repeat it.

Deferred

Prod sampling, by decision this session. It needs a release carrying this change to actually reach prod; the measurement stays open on #350 and remains the gate on any cold-start optimization. Nothing should be optimized off the old #350 numbers.

## Closed — shipped in PR #482 (merged, CI green @ `37674d65`) ### What landed The `HLS cold-start` line now sub-splits `startup`: ``` startup split ThreeWay spans runEntry (prep 143ms + ffmpegInit 1290ms + firstGop 146ms) ``` - **`prep`** — ErsatzTV-side work before FFmpeg exists (playout-item resolution, pipeline build, graphics-engine spawn) - **`ffmpegInit`** — FFmpeg launch → its first `-progress` output - **`firstGop`** — → `live.m3u8` exists Log-only: no transcode behavior change, no endpoint, no config knob. No API/SPA surface, so no doc or OpenAPI regen was owed. ### Read this before interpreting the data — the split does NOT resolve this issue's headline question The pipeline runs `-loglevel error -nostats -hide_banner`, so **a healthy FFmpeg writes nothing to stderr.** Input-open/probe therefore cannot be separated from encoder-init without changing the FFmpeg command — which this instrumentation must not do. `-progress` on stdout is the only zero-cost milestone available, so **`ffmpegInit` still contains BOTH rival hypotheses** (NFS input open *and* VAAPI init under contention). What is genuinely new is the **ErsatzTV-prep vs FFmpeg-time** boundary. The issue explicitly accepted a two-way outcome, so this is in scope — but if prod samples show `ffmpegInit` dominating (likely), the NFS-vs-VAAPI question is still open and needs a *different* instrument, or a deliberately-justified loglevel change. **Do not read a large `ffmpegInit` as evidence for either hypothesis.** ### Three caveats, documented on the type rather than left to be rediscovered 1. The buckets span the worker's `Run` entry, **not** the `startup` stopwatch — so `prep + ffmpegInit + firstGop` is a *superset* of `startup` (prep overlaps the tail of `setup`). Hence `spans runEntry` in the log line itself. **Do not subtract these from `startup`.** 2. The playlist is detected by a 100ms poll, so up to 100ms of error lands entirely in `firstGop`, the smallest bucket — and can flip a sample between `ThreeWay` and `TwoWayLateProgress`. 3. If the session's first FFmpeg process fails and a second produces the playlist, `ffmpegInit` spans the retry. ### Design stance: degrade, never invent Milestones are recorded on the worker thread and read on the request thread, so ordering is **validated, not assumed**. Any missing/out-of-order milestone degrades to a coarser `splitKind` (`ThreeWay` → `TwoWay`/`TwoWayLateProgress` → `Unavailable`) rather than producing a negative or fabricated bucket. A stale `live.m3u8` (possible when the pre-session folder wipe fails — `EmptyFolder` swallows failures into a warning) is reported `Unavailable` rather than as a plausible-looking sample. Milestones are set-once via `Interlocked`, so a long session's repeated `Transcode()` calls can't overwrite the cold-start numbers. ### Files `ColdStartStartupSplit.cs` (new, Core/FFmpeg), `PlaylistSegmentsResult.cs`, `HlsSessionWorker.cs`, `StartFFmpegSessionHandler.cs`, `ColdStartStartupSplitTests.cs` (new, 12 cases). ### Review Four cold-context adversarial passes, each over code the previous hadn't seen; every Medium-or-above fixed, none waived. Full record in [the PR comment](http://192.168.1.95:3000/timothy/ersatztv/pulls/482#issuecomment-13660). Notably, **two Mediums were the same defect class this PR exists to prevent** — a comment whose rationale didn't match the mechanism — each landed *inside* the fix for the previous one. One Low is accepted and documented rather than fixed (stated in that comment). ### Done-when: reworded, not quietly ticked The original checklist required prod samples *before* merge, which is circular — prod only runs this after a release. Split into pre-merge criteria (all met) and a post-release item now owned by #350. Rationale recorded in the issue body so the next instrumentation issue doesn't repeat it. ### Deferred Prod sampling, by decision this session. It needs a release carrying this change to actually reach prod; the measurement stays open on #350 and remains the gate on any cold-start optimization. **Nothing should be optimized off the old #350 numbers.**

timothy removed the in-progress label 2026-07-20 00:00:32 +02:00

timothy referenced this issue

2026-07-20 00:00:51 +02:00

Channel cold-start ~7s to first segment — slow tune-in via Dispatcharr/Kodi (heavy transcode profile) #350

timothy referenced this issue

2026-07-20 00:01:16 +02:00

ChicoryTV rewrite — queue tracker (goal, arc, session protocol) #237

timothy referenced this issue

2026-07-20 00:04:11 +02:00

Music channels dead: `Music Videos` library has no LibraryPath, so /data/music (30 folders) is never scanned — 8+ collections empty #474

timothy referenced this issue

2026-07-20 00:38:32 +02:00