ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs

@@ -131,9 +131,19 @@ public class StartFFmpegSessionHandler : IRequestHandler<StartFFmpegSession, Eit
         long startupMs = (long)segments.ProcessStartup.TotalMilliseconds;
         long fillMs = (long)segments.SegmentFill.TotalMilliseconds;
         long setupMs = Math.Max(0, totalMs - startupMs - fillMs);
+        // #472 sub-splits the startup work (81% of total, all of the variance) into the ErsatzTV-side
+        // prep before FFmpeg is launched, FFmpeg's own init (input open+probe and decoder/encoder
+        // init), and the wait for the playlist once FFmpeg is reporting progress. splitKind says how
+        // much of that was actually observable for this sample. NOTE these buckets span the worker's
+        // Run entry rather than the startup stopwatch, so they do NOT sum to startupMs — prep overlaps
+        // the tail of setup. The log says "spans runEntry" so a reader can't miss it.
+        // See ColdStartStartupSplit for the full set of caveats.
+        ColdStartStartupSplit split = segments.StartupSplit;
         _logger.LogInformation(
             "HLS cold-start channel {Channel} mode {Mode}: total {TotalMs}ms " +
             "(setup {SetupMs}ms + startup {ProcessStartupMs}ms + fill {SegmentFillMs}ms), " +
+            "startup split {SplitKind} spans runEntry (prep {PrepMs}ms + ffmpegInit {FFmpegInitMs}ms " +
+            "+ firstGop {FirstGopMs}ms), " +
             "segments {SegmentsReached}/{InitialSegmentCount}, " +
             "deadlineExpired {DeadlineExpired}, subtitleBurnIn {SubtitleBurnIn}, hwaccel {HwAccel}",
             request.ChannelNumber,
@@ -142,6 +152,10 @@ public class StartFFmpegSessionHandler : IRequestHandler<StartFFmpegSession, Eit
             setupMs,
             startupMs,
             fillMs,
+            split.Kind,
+            (long)split.Prep.TotalMilliseconds,
+            (long)split.FFmpegInit.TotalMilliseconds,
+            (long)split.FirstGop.TotalMilliseconds,
             segments.SegmentsReached,
             segments.InitialSegmentCount,
             segments.DeadlineExpired,

ErsatzTV.Application/Streaming/HlsSessionWorker.cs

@@ -61,6 +61,14 @@ public class HlsSessionWorker : IHlsSessionWorker
     // segments cannot exist until this process ran) — volatile for cross-thread visibility.
     private volatile string _coldStartFFmpegArguments;
 
+    // Stopwatch timestamps of the cold-start milestones used to sub-split the "startup" phase (#472).
+    // Each is written once on the sequential Run loop and read on the handler thread from
+    // WaitForPlaylistSegments; long fields cannot be volatile, so access goes through Volatile/
+    // Interlocked. Zero means "never reached", which ColdStartStartupSplit degrades gracefully on.
+    private long _coldStartRunTicks;
+    private long _coldStartProcessLaunchedTicks;
+    private long _coldStartFirstProgressTicks;
+
     public HlsSessionWorker(
         IServiceScopeFactory serviceScopeFactory,
         IGraphicsEngine graphicsEngine,
@@ -187,6 +195,10 @@ public class HlsSessionWorker : IHlsSessionWorker
     {
         _cancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(incomingCancellationToken);
 
+        // anchor for the cold-start startup sub-split (#472); this runs before any later milestone,
+        // so every sub-phase derived from it is non-negative by construction
+        Volatile.Write(ref _coldStartRunTicks, Stopwatch.GetTimestamp());
+
         try
         {
             _channelNumber = channelNumber;
@@ -314,6 +326,7 @@ public class HlsSessionWorker : IHlsSessionWorker
 
         var sw = Stopwatch.StartNew();
         var processStartup = TimeSpan.Zero;
+        var startupSplit = ColdStartStartupSplit.Unavailable;
         var segmentCount = 0;
         try
         {
@@ -329,6 +342,13 @@ public class HlsSessionWorker : IHlsSessionWorker
             _logger.LogDebug("Playlist exists");
             processStartup = sw.Elapsed;
 
+            // #472: sub-split the phase that #350 measured as 81% of cold-start and all of its variance
+            startupSplit = ColdStartStartupSplit.FromTimestamps(
+                Volatile.Read(ref _coldStartRunTicks),
+                Volatile.Read(ref _coldStartProcessLaunchedTicks),
+                Volatile.Read(ref _coldStartFirstProgressTicks),
+                Stopwatch.GetTimestamp());
+
             // start the segment-wait deadline only after the playlist file appears,
             // so slow pipeline setup (e.g. h264 profile probing) doesn't consume the budget
             DateTimeOffset finish = DateTimeOffset.Now.AddSeconds(8);
@@ -362,7 +382,8 @@ public class HlsSessionWorker : IHlsSessionWorker
                 segmentCount,
                 initialSegmentCount,
                 segmentCount < initialSegmentCount,
-                ColdStartFeatures.FromFFmpegArguments(_coldStartFFmpegArguments));
+                ColdStartFeatures.FromFFmpegArguments(_coldStartFFmpegArguments),
+                startupSplit);
         }
         finally
         {
@@ -576,10 +597,30 @@ public class HlsSessionWorker : IHlsSessionWorker
 
                     var progressParser = new FFmpegProgress();
 
+                    // #472: the first -progress line is the only cold-start milestone FFmpeg gives us
+                    // for free (the pipeline runs -loglevel error -nostats, so stderr stays silent on a
+                    // healthy run). It means the input is open and probed and the decoder/encoder are
+                    // initialized. Record-once, so only the session's first process is measured.
+                    void ParseProgressLine(string line)
+                    {
+                        // the read short-circuits the timestamp call for every line after the first,
+                        // which is every line for the life of the session
+                        if (Volatile.Read(ref _coldStartFirstProgressTicks) == 0)
+                        {
+                            Interlocked.CompareExchange(ref _coldStartFirstProgressTicks, Stopwatch.GetTimestamp(), 0);
+                        }
+
+                        progressParser.ParseLine(line);
+                    }
+
+                    // everything before this point is ErsatzTV-side "prep" (playout item resolution,
+                    // pipeline build, graphics engine spawn); FFmpeg's own clock starts here
+                    Interlocked.CompareExchange(ref _coldStartProcessLaunchedTicks, Stopwatch.GetTimestamp(), 0);
+
                     CommandResult commandResult = await processWithPipe
                         .WithWorkingDirectory(_workingDirectory)
                         .WithStandardErrorPipe(PipeTarget.ToStringBuilder(stdErrBuffer))
-                        .WithStandardOutputPipe(PipeTarget.ToDelegate(progressParser.ParseLine))
+                        .WithStandardOutputPipe(PipeTarget.ToDelegate(ParseProgressLine))
                         .WithValidation(CommandResultValidation.None)
                         .ExecuteAsync(linkedCts.Token);
 

ErsatzTV.Core.Tests/FFmpeg/ColdStartStartupSplitTests.cs

@@ -0,0 +1,171 @@
+using System.Diagnostics;
+using ErsatzTV.Core.FFmpeg;
+using NUnit.Framework;
+using Shouldly;
+
+namespace ErsatzTV.Core.Tests.FFmpeg;
+
+[TestFixture]
+public class ColdStartStartupSplitTests
+{
+    // milestones are Stopwatch.GetTimestamp() values; build them from a base + millisecond offsets
+    private const long Base = 1_000_000_000;
+
+    private static long At(double milliseconds) =>
+        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);
+    }
+}

ErsatzTV.Core/FFmpeg/ColdStartStartupSplit.cs

@@ -0,0 +1,146 @@
+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;
+    }
+}

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); <see cref="SegmentFill"/> is Phase B (playlist
 /// exists -&gt; the requested number of segments are present, or the 8s deadline).
+/// <see cref="StartupSplit"/> breaks Phase A down further (#472).
 /// </summary>
 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);