Files
ersatztv/ErsatzTV.Core/FFmpeg/ColdStartStartupSplit.cs
T
timothy 37674d6519
Build ErsatzTV Image / CI image pin matches docker/ci (pull_request) Successful in 9s
Build ErsatzTV Image / Docs update reminder (pull_request) Successful in 46s
Build ErsatzTV Image / decisions.md append-only (pull_request) Successful in 10s
Build ErsatzTV Image / API docs in sync (OpenAPI + endpoint index) (pull_request) Successful in 17s
Build ErsatzTV Image / Formatting (changed .cs conform to .editorconfig) (pull_request) Successful in 18s
Build ErsatzTV Image / Build & test (.NET) (pull_request) Successful in 7m24s
Build ErsatzTV Image / EF migration integrity (SQLite + MySql) (pull_request) Successful in 14m22s
Build ErsatzTV Image / Functional E2E (curl contracts) (pull_request) Successful in 14m25s
Build ErsatzTV Image / Build & push image (amd64) (pull_request) Has been skipped
test(472): name the stale-playlist test for what it actually pins
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.
2026-07-19 23:33:28 +02:00

147 lines
7.2 KiB
C#

using System.Diagnostics;
namespace ErsatzTV.Core.FFmpeg;
/// <summary>
/// How finely a cold-start's startup work could be broken down (#472).
/// </summary>
public enum ColdStartStartupSplitKind
{
/// <summary>
/// No split available: the FFmpeg process was never launched, the playlist never appeared, or the
/// playlist was observed before FFmpeg was launched (a stale playlist left behind because the
/// pre-session transcode-folder wipe failed — it logs a warning and continues).
/// </summary>
Unavailable = 0,
/// <summary>
/// Two-way split: <c>prep</c> + <c>ffmpegInit</c>, because FFmpeg emitted no progress output at all
/// before the playlist appeared. <c>ffmpegInit</c> therefore runs to the playlist.
/// </summary>
TwoWay = 1,
/// <summary>
/// Two-way split, distinguished because FFmpeg <em>did</em> report progress but only after the
/// playlist was observed. Same buckets as <see cref="TwoWay"/>; kept separate because it means the
/// playlist appeared before the first progress report rather than FFmpeg being silent, which is a
/// different story about the pipeline (and is also what the 100ms playlist poll can manufacture).
/// </summary>
TwoWayLateProgress = 2,
/// <summary>Three-way split: <c>prep</c> + <c>ffmpegInit</c> + <c>firstGop</c>.</summary>
ThreeWay = 3
}
/// <summary>
/// Sub-split of the HLS cold-start startup work (#472), which #350's measurement showed to be 81% of
/// tune-in latency and to carry 100% of its variance while remaining a single opaque bucket.
/// <para>
/// <see cref="Prep"/> is ErsatzTV-side work before FFmpeg exists: playout-item resolution, pipeline
/// build, graphics-engine spawn. <see cref="FFmpegInit"/> is FFmpeg from launch until it first reports
/// progress — input open + probe (the NFS hypothesis) plus decoder/encoder init (the VAAPI-contention
/// hypothesis). <see cref="FirstGop"/> is from that first progress report until <c>live.m3u8</c> exists.
/// </para>
/// <para>
/// <b>These buckets span the session worker's <c>Run</c> entry to the playlist appearing, which is NOT
/// exactly the logged <c>startup</c> phase</b>: the worker is launched fire-and-forget slightly before
/// the request thread starts the <c>startup</c> stopwatch, so <see cref="Prep"/> overlaps the tail of
/// the logged <c>setup</c> bucket (in practice one config read). Do not expect
/// <c>prep + ffmpegInit + firstGop</c> to equal <c>startup</c> — it is a superset by that overlap.
/// </para>
/// <para>
/// Because the pipeline runs <c>-loglevel error -nostats -hide_banner</c>, a healthy FFmpeg writes
/// nothing to stderr, so input-open and encoder-init cannot be separated from each other without
/// changing the FFmpeg command — which this instrumentation deliberately does not do. The
/// <c>-progress</c> stream on stdout is therefore the only zero-cost milestone available, and
/// <see cref="FFmpegInit"/> necessarily lumps those two candidates together. #472 accepts this: a
/// large <see cref="Prep"/> vs a large <see cref="FFmpegInit"/> is itself the first discrimination,
/// and it is honest about what it cannot yet see.
/// </para>
/// <para>
/// Three further caveats when reading these numbers. The playlist is detected by a 100ms poll, so its
/// timestamp is up to 100ms late and that error lands entirely in <see cref="FirstGop"/> — the
/// smallest bucket — and can also flip a sample between <see cref="ColdStartStartupSplitKind.ThreeWay"/>
/// and <see cref="ColdStartStartupSplitKind.TwoWayLateProgress"/>. And if the session's first FFmpeg
/// process fails and a second one produces the playlist, <see cref="FFmpegInit"/> spans the first
/// process's whole lifetime plus the retry while still being labelled as one process's init. And the
/// stale-playlist guard below is best-effort rather than a proof: if the folder wipe failed, whether
/// the stale playlist is observed before or after the launch milestone is a scheduling race, so an
/// unlucky sample could still slip through as an implausibly fast one (most often
/// <see cref="ColdStartStartupSplitKind.TwoWay"/>, since FFmpeg has usually not reported progress
/// that early).
/// </para>
/// </summary>
public readonly record struct ColdStartStartupSplit(
TimeSpan Prep,
TimeSpan FFmpegInit,
TimeSpan FirstGop,
ColdStartStartupSplitKind Kind)
{
public static readonly ColdStartStartupSplit Unavailable =
new(TimeSpan.Zero, TimeSpan.Zero, TimeSpan.Zero, ColdStartStartupSplitKind.Unavailable);
/// <summary>
/// Builds the split from four <see cref="Stopwatch.GetTimestamp"/> milestones; <c>0</c> means the
/// milestone never happened. Milestones are recorded on different threads (the session worker
/// records the launch and progress ones; the request thread observes the playlist), so ordering is
/// validated rather than assumed: any out-of-order or missing milestone degrades the result to a
/// coarser <see cref="ColdStartStartupSplitKind"/> instead of producing a negative or invented bucket.
/// </summary>
public static ColdStartStartupSplit FromTimestamps(
long runStarted,
long processLaunched,
long firstProgress,
long playlistExists)
{
if (runStarted <= 0 || processLaunched <= 0 || playlistExists <= 0)
{
return Unavailable;
}
if (processLaunched > playlistExists)
{
// the playlist was observed before FFmpeg was even launched, so it is a stale file: the
// handler wipes the transcode folder before starting the session, but that wipe swallows
// its failures into a warning (LocalFileSystem.EmptyFolder) and continues.
// Every bucket would be meaningless; report nothing rather than a plausible-looking sample
return Unavailable;
}
// the worker's Run entry strictly precedes every later milestone; clamp anyway so a clock
// oddity can never surface as a negative duration in telemetry
TimeSpan prep = Elapsed(runStarted, processLaunched);
if (firstProgress <= 0 || firstProgress < processLaunched)
{
// FFmpeg reported no usable progress before the playlist appeared: fall back to the two-way
// split #472 explicitly accepts, rather than inventing a boundary that was never observed
return new ColdStartStartupSplit(
prep,
Elapsed(processLaunched, playlistExists),
TimeSpan.Zero,
ColdStartStartupSplitKind.TwoWay);
}
if (firstProgress > playlistExists)
{
return new ColdStartStartupSplit(
prep,
Elapsed(processLaunched, playlistExists),
TimeSpan.Zero,
ColdStartStartupSplitKind.TwoWayLateProgress);
}
return new ColdStartStartupSplit(
prep,
Elapsed(processLaunched, firstProgress),
Elapsed(firstProgress, playlistExists),
ColdStartStartupSplitKind.ThreeWay);
}
private static TimeSpan Elapsed(long from, long to)
{
TimeSpan elapsed = Stopwatch.GetElapsedTime(from, to);
return elapsed < TimeSpan.Zero ? TimeSpan.Zero : elapsed;
}
}