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

Merged

timothy merged 4 commits from feat/472-startup-subsplit into main 2026-07-19 23:59:23 +02:00

Conversation 1 Commits 4 Files Changed 5

+377 -3

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

Owner

Copy Link

Copy Source

fixes #472

#350's measurement showed startup is 81% of tune-in latency and carries 100% of its variance, while remaining one opaque bucket spanning FFmpeg spawn → input open/probe → decoder/encoder init → first GOP. Two rival hypotheses survived that measurement (NFS input open vs VAAPI init under GPU contention) and they need opposite fixes, so this splits before anyone optimizes.

What lands

Extends the existing Information-level HLS cold-start line with a sub-split of 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 new endpoint, no config knob — consistent with #446. No API/SPA surface, so no OpenAPI or doc regen.

The limitation, stated rather than papered over

The pipeline runs -loglevel error -nostats -hide_banner, so a healthy FFmpeg writes nothing to stderr. Input-open and encoder-init therefore cannot be separated from each other without changing the FFmpeg command, which this instrumentation must not do. -progress on stdout is the only zero-cost milestone available, so ffmpegInit still lumps the two rival hypotheses together.

What the split does newly discriminate is ErsatzTV-side prep vs FFmpeg's own time — and #472 explicitly accepts the two-way form as sufficient. This is written into the type's doc comment so the next reader doesn't over-claim from the data.

Three further caveats are documented on ColdStartStartupSplit rather than left for someone to rediscover:

• 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;
• the playlist is detected by a 100ms poll, so that error lands entirely in firstGop, the smallest bucket;
• if the session's first FFmpeg process fails and a second produces the playlist, ffmpegInit spans the retry.

Degradation, not invention

Milestones are recorded on the worker thread and read on the request thread, so ordering is validated, never assumed. Every missing or out-of-order milestone degrades to a coarser splitKind (ThreeWay → TwoWay / TwoWayLateProgress → Unavailable) instead of producing a negative or invented bucket. A stale live.m3u8 from a previous session (Run warns about a non-empty transcode folder but does not delete it) is explicitly reported as Unavailable rather than as a plausible-looking sample.

Milestones are set-once via Interlocked.CompareExchange, so the repeated Transcode() calls in a long session cannot overwrite the cold-start numbers.

Verification

• Build succeeded; full suite green (3903 tests, 0 failed)
• 11 new pure unit tests on the timing logic (ColdStartFeaturesTests precedent), covering the fallbacks, the stale-playlist guard, progress-before-launch, and boundary equality — so tightening >= to > later cannot pass silently
• BOM check clean on the touched .cs set; dotnet format --verify-no-changes clean
• Cold-context adversarial review ran over the first commit: no blockers, no transcode-behavior change, no thread-safety defect. Its Medium/Low findings are all addressed in the second commit (see that commit message).

Not done here

The last ## Done-when box — fresh prod samples posted to #350 — needs this to reach prod, so it stays unticked until then rather than being ticked on a local run.

fixes #472 #350's measurement showed `startup` is **81% of tune-in latency and carries 100% of its variance**, while remaining one opaque bucket spanning FFmpeg spawn → input open/probe → decoder/encoder init → first GOP. Two rival hypotheses survived that measurement (NFS input open vs VAAPI init under GPU contention) and they need **opposite** fixes, so this splits before anyone optimizes. ## What lands Extends the existing Information-level `HLS cold-start` line with a sub-split of `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 new endpoint, no config knob — consistent with #446. No API/SPA surface, so no OpenAPI or doc regen. ## The limitation, stated rather than papered over The pipeline runs `-loglevel error -nostats -hide_banner`, so a **healthy FFmpeg writes nothing to stderr**. Input-open and encoder-init therefore cannot be separated from each other without changing the FFmpeg command, which this instrumentation must not do. `-progress` on stdout is the only zero-cost milestone available, so **`ffmpegInit` still lumps the two rival hypotheses together.** What the split *does* newly discriminate is ErsatzTV-side prep vs FFmpeg's own time — and #472 explicitly accepts the two-way form as sufficient. This is written into the type's doc comment so the next reader doesn't over-claim from the data. Three further caveats are documented on `ColdStartStartupSplit` rather than left for someone to rediscover: - 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; - the playlist is detected by a 100ms poll, so that error lands entirely in `firstGop`, the smallest bucket; - if the session's first FFmpeg process fails and a second produces the playlist, `ffmpegInit` spans the retry. ## Degradation, not invention Milestones are recorded on the worker thread and read on the request thread, so ordering is **validated, never assumed**. Every missing or out-of-order milestone degrades to a coarser `splitKind` (`ThreeWay` → `TwoWay` / `TwoWayLateProgress` → `Unavailable`) instead of producing a negative or invented bucket. A stale `live.m3u8` from a previous session (`Run` warns about a non-empty transcode folder but does not delete it) is explicitly reported as `Unavailable` rather than as a plausible-looking sample. Milestones are set-once via `Interlocked.CompareExchange`, so the repeated `Transcode()` calls in a long session cannot overwrite the cold-start numbers. ## Verification - Build succeeded; **full suite green** (3903 tests, 0 failed) - 11 new pure unit tests on the timing logic (`ColdStartFeaturesTests` precedent), covering the fallbacks, the stale-playlist guard, progress-before-launch, and boundary equality — so tightening `>=` to `>` later cannot pass silently - BOM check clean on the touched `.cs` set; `dotnet format --verify-no-changes` clean - Cold-context adversarial review ran over the first commit: **no blockers, no transcode-behavior change, no thread-safety defect**. Its Medium/Low findings are all addressed in the second commit (see that commit message). ## Not done here The last `## Done-when` box — fresh prod samples posted to #350 — needs this to reach prod, so it stays unticked until then rather than being ticked on a local run.

timothy added 2 commits 2026-07-19 23:05:44 +02:00

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

#350's measurement showed `startup` is 81% of tune-in latency and carries
100% of its variance, while remaining one opaque bucket spanning FFmpeg
spawn -> input open/probe -> encoder init -> first GOP. Two hypotheses
survive that measurement (NFS input open vs VAAPI init under contention)
and they need opposite fixes, so split before optimizing.

Adds `prep` (ErsatzTV-side work before FFmpeg exists) + `ffmpegInit`
(launch -> first `-progress` output) + `firstGop` (-> live.m3u8 exists)
to the existing Information-level cold-start line.

The pipeline runs `-loglevel error -nostats -hide_banner`, so a healthy
FFmpeg writes nothing to stderr; the `-progress` stream is the only
zero-cost milestone available and `ffmpegInit` therefore still lumps
input-open with encoder-init. That limit is documented rather than
papered over, and the split degrades to the two-way form #472 accepts
when no progress arrives before the playlist.

Log-only: no transcode behavior change, no new endpoint or config knob.

fixes #472

fix(472): review fixes — honest bucket boundaries, stale-playlist guard ... 757fb76151

From the cold adversarial review of the initial diff. No blockers were
found; these address what the numbers MEAN, which is the whole point of
an instrumentation change.

- The buckets span the worker's Run entry, not the startup stopwatch, so
  prep overlaps the tail of `setup`. Rather than let the log imply an
  invariant it does not satisfy, say "spans runEntry" in the line, spell
  it out in the doc comment, and rename the test that had codified the
  false `sum == startup` claim.
- Guard `processLaunched > playlistExists` -> Unavailable: a stale
  live.m3u8 from a previous session (Run warns about a non-empty
  transcode folder but does not delete it) would otherwise yield a
  plausible-looking sample whose prep exceeds the measured phase.
- Split the two-way fallback into TwoWay vs TwoWayLateProgress. They are
  different stories about the pipeline and discriminating stories is
  what this issue is for.
- Document the 100ms playlist-poll quantization (it lands entirely in
  firstGop, the smallest bucket) and the first-process-failed case where
  ffmpegInit spans a retry.
- Short-circuit the per-line timestamp call; static readonly Unavailable.
- Tests for the new guard, progress-before-launch, and boundary equality
  (so tightening >= to > later cannot pass silently).

timothy added 1 commit 2026-07-19 23:21:17 +02:00

docs(472): correct the stale-playlist rationale; pin guard precedence ... 58b93d3e3d

Re-review of the fix commit returned MERGEABLE with one Medium: the
comment justifying the stale-playlist guard misstated the mechanism, in
three places. It claimed Run "warns about a non-empty transcode folder
but does not delete it" — but StartFFmpegSessionHandler.FolderMustBeEmpty
calls EmptyFolder BEFORE the worker spawns, and Run's finally empties it
again. Verified directly rather than taken on the reviewer's word.

The real residual path is EmptyFolder FAILING: it swallows every
exception into a LogWarning and continues. Say that instead.

On a PR whose entire value is that the numbers mean what they say, a
rationale comment that misstates the mechanism is the same class of
defect the PR exists to prevent, so it does not get to ship as a nit.

Also documents that the guard is best-effort rather than a proof (if the
wipe failed, before-or-after-launch is a scheduling race, so an unlucky
sample can still slip through as an implausibly fast ThreeWay), and adds
the test the reviewer noted was missing: guard precedence over an
otherwise-valid ThreeWay.

Comments and one test only; no logic change.

timothy added 1 commit 2026-07-19 23:41:42 +02:00

test(472): name the stale-playlist test for what it actually pins ... 37674d6519

Third-round review caught that
Stale_Playlist_Guard_Should_Take_Precedence_Over_An_Otherwise_Valid_Three_Way
describes an impossible case: ThreeWay requires
processLaunched <= playlistExists, which is exactly the negation of the
guard condition, so the guard can never preempt a ThreeWay. What the
test really pins is precedence over the progress branches
(TwoWayLateProgress) — still the ordering that matters.

That is the same "rationale misstates the mechanism" defect the previous
commit existed to fix, landed inside the fix itself. Renaming rather
than leaving a test whose name teaches the next reader something false.

Also broadens the escape-hatch caveat: a stale playlist that slips past
the guard lands as TwoWay more often than ThreeWay, since FFmpeg has
usually not reported progress that early.

Test name and comments only; no logic change.

timothy commented 2026-07-19 23:44:34 +02:00

Author

Owner

Copy Link

Copy Source

Review record (three cold-context adversarial passes)

Each pass reviewed the new code the previous one had not seen, per the "re-review the fix commit" rule — the fix commit is always code no reviewer has looked at.

pass	head reviewed	outcome
1	d91d6ee1 (initial)	No blockers, no transcode-behavior change, no thread-safety defect. 3 Mediums + 2 Lows
2	757fb761 (review fixes)	MERGEABLE. 1 Medium: the stale-playlist rationale misstated the mechanism
3	58b93d3e (rationale fix)	MERGEABLE. 1 Medium: a test name described an impossible case
4	37674d65 (test rename)	MERGEABLE

Everything Medium-or-above was fixed rather than waived. Two of those Mediums were the same defect class this PR exists to prevent — a comment whose stated rationale doesn't match the mechanism — landed inside the fixes for the previous one. Worth recording, since instrumentation whose rationale is wrong is worse than none: it produces confident misreadings.

I verified pass 2's and pass 3's central claims against the source myself rather than taking the reviewer's word (FolderMustBeEmpty really does call EmptyFolder before the worker spawns; EmptyFolder really does swallow failures into a warning; ThreeWay really is unreachable past the guard).

Accepted and documented, not fixed

Pass 4 raised one Low: the inline comment on ParseProgressLine (HlsSessionWorker.cs) says "only the session's first process is measured", but strictly the record-once captures the first progress line of the session, which belongs to the second FFmpeg process if the first died silently. The telemetry itself is honest — ColdStartStartupSplit's class doc already spells this exact case out ("FFmpegInit spans the first process's whole lifetime plus the retry"). Only the inline comment overstates.

I'm deliberately not spending a fourth CI cycle on it. I fixed this class twice already; the distinguishing factor is that here the adjacent authoritative doc states the truth, and the overstatement concerns which process, not what the number means. Flagging it openly rather than silently dropping it.

CI cost, stated

This branch consumed three CI runs. The second push superseded a live run for 757fb761 that I could not cancel (this Gitea's cancel routes 404 from the agent side), so it held a runner slot while draining. The third push waited for green before landing, so nothing was orphaned.

Review-verdict: MERGEABLE @ 37674d6519

## Review record (three cold-context adversarial passes) Each pass reviewed the *new* code the previous one had not seen, per the "re-review the fix commit" rule — the fix commit is always code no reviewer has looked at. | pass | head reviewed | outcome | |---|---|---| | 1 | `d91d6ee1` (initial) | No blockers, no transcode-behavior change, no thread-safety defect. 3 Mediums + 2 Lows | | 2 | `757fb761` (review fixes) | MERGEABLE. 1 Medium: the stale-playlist rationale misstated the mechanism | | 3 | `58b93d3e` (rationale fix) | MERGEABLE. 1 Medium: a test name described an impossible case | | 4 | `37674d65` (test rename) | MERGEABLE | Everything Medium-or-above was fixed rather than waived. Two of those Mediums were the *same defect class this PR exists to prevent* — a comment whose stated rationale doesn't match the mechanism — landed inside the fixes for the previous one. Worth recording, since instrumentation whose rationale is wrong is worse than none: it produces confident misreadings. I verified pass 2's and pass 3's central claims against the source myself rather than taking the reviewer's word (`FolderMustBeEmpty` really does call `EmptyFolder` before the worker spawns; `EmptyFolder` really does swallow failures into a warning; `ThreeWay` really is unreachable past the guard). ### Accepted and documented, not fixed Pass 4 raised one **Low**: the inline comment on `ParseProgressLine` (`HlsSessionWorker.cs`) says "only the session's first process is measured", but strictly the record-once captures the first progress line *of the session*, which belongs to the second FFmpeg process if the first died silently. **The telemetry itself is honest** — `ColdStartStartupSplit`'s class doc already spells this exact case out ("`FFmpegInit` spans the first process's whole lifetime plus the retry"). Only the inline comment overstates. I'm deliberately not spending a fourth CI cycle on it. I fixed this class twice already; the distinguishing factor is that here the adjacent authoritative doc states the truth, and the overstatement concerns *which process*, not what the number means. Flagging it openly rather than silently dropping it. ### CI cost, stated This branch consumed three CI runs. The second push superseded a live run for `757fb761` that I could not cancel (this Gitea's cancel routes 404 from the agent side), so it held a runner slot while draining. The third push waited for green before landing, so nothing was orphaned. Review-verdict: MERGEABLE @ 37674d6519d9655204a7def06fbac7466075a30d

timothy merged commit ab25658643 into main 2026-07-19 23:59:23 +02:00

timothy deleted branch feat/472-startup-subsplit 2026-07-19 23:59:23 +02:00

timothy referenced this issue from a commit 2026-07-19 23:59:23 +02:00

Merge pull request 'feat(472): sub-split the HLS cold-start startup phase' (#482) from feat/472-startup-subsplit into main

timothy referenced this pull request 2026-07-20 00:00:21 +02:00

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

timothy referenced this pull request 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 pull request 2026-07-20 00:01:16 +02:00

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

timothy referenced this pull request 2026-07-20 17:23:47 +02:00

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

timothy referenced this pull request 2026-07-20 21:44:42 +02:00

External-URL channel logos never render an on-screen bug (File.Exists against a URL in WatermarkSelector) #502

timothy referenced this pull request 2026-07-26 00:43:12 +02:00

fix(617): make the cross-repo skills real symlinks and reconcile the ersatztv skill #639

Sign in to join this conversation.

Reviewers

No Reviewers

Labels

Clear labels

ad-hoc

One-off / ad-hoc work not tracked by a dedicated issue

api

REST API / HTTP endpoints

bug

Something isn't working

ci-cd

Build, test, deploy pipeline

content

Channel content / schedules / playlists

dependencies

Dependency updates (Renovate)

enhancement

New feature or improvement

frontend

ChicoryTV React SPA frontend

in-progress

Claimed by an active session — do not pick up

jellyfin

Jellyfin tuner / IPTV integration

parked

Excluded from automatic queue pickup; work only when explicitly selected

priority: high

priority: low

priority: medium

review

Adversarial review finding

security

Security / vulnerability fix

No labels

Milestone

No items

No Milestone

Projects

Clear projects

No projects

Assignees

Clear assignees

renovate timothy (Timothy)

No Assignees

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: timothy/ersatztv#482