diff --git a/ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs b/ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs index 6cc07bb99..abe01b94a 100644 --- a/ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs +++ b/ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs @@ -131,9 +131,19 @@ public class StartFFmpegSessionHandler : IRequestHandler + Base + (long)(milliseconds / 1000.0 * Stopwatch.Frequency); + + [Test] + public void Should_Split_Three_Ways_When_All_Milestones_Present() + { + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(150), + At(1200), + At(1600)); + + split.Kind.ShouldBe(ColdStartStartupSplitKind.ThreeWay); + split.Prep.TotalMilliseconds.ShouldBe(150, 1); + split.FFmpegInit.TotalMilliseconds.ShouldBe(1050, 1); + split.FirstGop.TotalMilliseconds.ShouldBe(400, 1); + } + + [Test] + public void Sub_Phases_Should_Sum_To_Run_Entry_Through_Playlist() + { + // deliberately NOT "should sum to startup": the buckets span the worker's Run entry, which + // begins before the request thread's startup stopwatch, so prep overlaps the tail of setup + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(150), + At(1200), + At(1600)); + + (split.Prep + split.FFmpegInit + split.FirstGop).TotalMilliseconds.ShouldBe(1600, 1); + } + + [Test] + public void Should_Be_Unavailable_When_The_Playlist_Predates_The_Process_Launch() + { + // a stale live.m3u8 survives when the handler's pre-session folder wipe fails (EmptyFolder + // swallows the failure into a warning). Every bucket would be meaningless, so report nothing + // rather than a plausible-looking sample with a prep that exceeds the whole measured phase + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(1600), + 0, + At(150)); + + split.ShouldBe(ColdStartStartupSplit.Unavailable); + } + + [Test] + public void Stale_Playlist_Guard_Should_Take_Precedence_Over_The_Progress_Branches() + { + // without the guard, this input would be classified TwoWayLateProgress; the guard must be + // evaluated first. (It can never preempt a ThreeWay: that requires processLaunched <= + // playlistExists, which is exactly the negation of the guard condition.) + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(1600), + At(1700), + At(150)); + + split.ShouldBe(ColdStartStartupSplit.Unavailable); + } + + [Test] + public void Should_Fall_Back_To_Two_Way_Split_When_Progress_Predates_The_Process_Launch() + { + // a progress timestamp older than the launch cannot belong to this process + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(100), + At(150), + At(120), + At(1600)); + + split.Kind.ShouldBe(ColdStartStartupSplitKind.TwoWay); + split.FFmpegInit.TotalMilliseconds.ShouldBe(1450, 1); + split.FirstGop.ShouldBe(TimeSpan.Zero); + } + + [Test] + public void Should_Stay_Three_Way_When_Progress_Coincides_With_A_Boundary() + { + ColdStartStartupSplit atLaunch = ColdStartStartupSplit.FromTimestamps(At(0), At(150), At(150), At(1600)); + atLaunch.Kind.ShouldBe(ColdStartStartupSplitKind.ThreeWay); + atLaunch.FFmpegInit.ShouldBe(TimeSpan.Zero); + atLaunch.FirstGop.TotalMilliseconds.ShouldBe(1450, 1); + + ColdStartStartupSplit atPlaylist = ColdStartStartupSplit.FromTimestamps(At(0), At(150), At(1600), At(1600)); + atPlaylist.Kind.ShouldBe(ColdStartStartupSplitKind.ThreeWay); + atPlaylist.FFmpegInit.TotalMilliseconds.ShouldBe(1450, 1); + atPlaylist.FirstGop.ShouldBe(TimeSpan.Zero); + } + + [Test] + public void Should_Fall_Back_To_Two_Way_Split_When_FFmpeg_Never_Reported_Progress() + { + // no -progress output before the playlist appeared: ffmpegInit must absorb the remainder + // rather than the split inventing a firstGop boundary that was never observed + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(150), + 0, + At(1600)); + + split.Kind.ShouldBe(ColdStartStartupSplitKind.TwoWay); + split.Prep.TotalMilliseconds.ShouldBe(150, 1); + split.FFmpegInit.TotalMilliseconds.ShouldBe(1450, 1); + split.FirstGop.ShouldBe(TimeSpan.Zero); + } + + [Test] + public void Should_Report_Late_Progress_Distinctly_When_Progress_Arrived_After_The_Playlist() + { + // the playlist is observed on the request thread while progress is recorded on the worker + // thread; a progress milestone outside the phase must not produce a negative bucket + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(0), + At(150), + At(1800), + At(1600)); + + split.Kind.ShouldBe(ColdStartStartupSplitKind.TwoWayLateProgress); + split.FFmpegInit.TotalMilliseconds.ShouldBe(1450, 1); + split.FirstGop.ShouldBe(TimeSpan.Zero); + } + + [TestCase(0L, 150L, 1200L, 1600L, TestName = "Run never started")] + [TestCase(100L, 0L, 0L, 1600L, TestName = "Process never launched")] + [TestCase(100L, 150L, 1200L, 0L, TestName = "Playlist never appeared")] + public void Should_Be_Unavailable_When_A_Required_Milestone_Is_Missing( + long runStarted, + long processLaunched, + long firstProgress, + long playlistExists) + { + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + runStarted == 0 ? 0 : At(runStarted), + processLaunched == 0 ? 0 : At(processLaunched), + firstProgress == 0 ? 0 : At(firstProgress), + playlistExists == 0 ? 0 : At(playlistExists)); + + split.ShouldBe(ColdStartStartupSplit.Unavailable); + } + + [Test] + public void Should_Clamp_Rather_Than_Report_A_Negative_Prep() + { + // defensive: launch cannot precede Run entry, but telemetry must never show a negative + ColdStartStartupSplit split = ColdStartStartupSplit.FromTimestamps( + At(500), + At(150), + At(1200), + At(1600)); + + split.Prep.ShouldBe(TimeSpan.Zero); + split.Kind.ShouldBe(ColdStartStartupSplitKind.ThreeWay); + split.FFmpegInit.TotalMilliseconds.ShouldBe(1050, 1); + split.FirstGop.TotalMilliseconds.ShouldBe(400, 1); + } +} diff --git a/ErsatzTV.Core/FFmpeg/ColdStartStartupSplit.cs b/ErsatzTV.Core/FFmpeg/ColdStartStartupSplit.cs new file mode 100644 index 000000000..a94df97cd --- /dev/null +++ b/ErsatzTV.Core/FFmpeg/ColdStartStartupSplit.cs @@ -0,0 +1,146 @@ +using System.Diagnostics; + +namespace ErsatzTV.Core.FFmpeg; + +/// +/// How finely a cold-start's startup work could be broken down (#472). +/// +public enum ColdStartStartupSplitKind +{ + /// + /// 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). + /// + Unavailable = 0, + + /// + /// Two-way split: prep + ffmpegInit, because FFmpeg emitted no progress output at all + /// before the playlist appeared. ffmpegInit therefore runs to the playlist. + /// + TwoWay = 1, + + /// + /// Two-way split, distinguished because FFmpeg did report progress but only after the + /// playlist was observed. Same buckets as ; 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). + /// + TwoWayLateProgress = 2, + + /// Three-way split: prep + ffmpegInit + firstGop. + ThreeWay = 3 +} + +/// +/// 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. +/// +/// is ErsatzTV-side work before FFmpeg exists: playout-item resolution, pipeline +/// build, graphics-engine spawn. is FFmpeg from launch until it first reports +/// progress — input open + probe (the NFS hypothesis) plus decoder/encoder init (the VAAPI-contention +/// hypothesis). is from that first progress report until live.m3u8 exists. +/// +/// +/// These buckets span the session worker's Run entry to the playlist appearing, which is NOT +/// exactly the logged startup phase: the worker is launched fire-and-forget slightly before +/// the request thread starts the startup stopwatch, so overlaps the tail of +/// the logged setup bucket (in practice one config read). Do not expect +/// prep + ffmpegInit + firstGop to equal startup — it is a superset by that overlap. +/// +/// +/// Because the pipeline runs -loglevel error -nostats -hide_banner, 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 +/// -progress stream on stdout is therefore the only zero-cost milestone available, and +/// necessarily lumps those two candidates together. #472 accepts this: a +/// large vs a large is itself the first discrimination, +/// and it is honest about what it cannot yet see. +/// +/// +/// 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 — the +/// smallest bucket — and can also flip a sample between +/// and . And if the session's first FFmpeg +/// process fails and a second one produces the playlist, 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 +/// , since FFmpeg has usually not reported progress +/// that early). +/// +/// +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); + + /// + /// Builds the split from four milestones; 0 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 instead of producing a negative or invented bucket. + /// + 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; + } +} diff --git a/ErsatzTV.Core/FFmpeg/PlaylistSegmentsResult.cs b/ErsatzTV.Core/FFmpeg/PlaylistSegmentsResult.cs index 83964430a..aeb30799b 100644 --- a/ErsatzTV.Core/FFmpeg/PlaylistSegmentsResult.cs +++ b/ErsatzTV.Core/FFmpeg/PlaylistSegmentsResult.cs @@ -6,6 +6,7 @@ namespace ErsatzTV.Core.FFmpeg; /// FFmpeg process spawn + probe + libass/encoder init + first GOP, since the wait begins right /// after the fire-and-forget worker is launched); is Phase B (playlist /// exists -> the requested number of segments are present, or the 8s deadline). +/// breaks Phase A down further (#472). /// public readonly record struct PlaylistSegmentsResult( TimeSpan ProcessStartup, @@ -13,4 +14,5 @@ public readonly record struct PlaylistSegmentsResult( int SegmentsReached, int InitialSegmentCount, bool DeadlineExpired, - ColdStartFeatures Features); + ColdStartFeatures Features, + ColdStartStartupSplit StartupSplit);