log warnings when transcoding speed is potentially insufficient (#2808)

* refactor parsing ffmpeg progress/speed

* log warnings when transcoding speed is potentially insufficient

* dont log progress on hls direct; fix tests

CHANGELOG.md

@@ -4,6 +4,9 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 
 ## [Unreleased]
+### Added
+- Add log warnings when actual transcoding speed is potentially insufficient to support smooth playback
+  - Log messages will include media item id, channel number and transcoding speed
 
 ## [26.2.0] - 2026-02-02
 ### Added

ErsatzTV.Application/Streaming/HlsSessionWorker.cs

@@ -528,9 +528,12 @@ public class HlsSessionWorker : IHlsSessionWorker
                             linkedCts.Token);
                     }
 
+                    var progressParser = new FFmpegProgress();
+
                     CommandResult commandResult = await processWithPipe
                         .WithWorkingDirectory(_workingDirectory)
                         .WithStandardErrorPipe(PipeTarget.ToStringBuilder(stdErrBuffer))
+                        .WithStandardOutputPipe(PipeTarget.ToDelegate(progressParser.ParseLine))
                         .WithValidation(CommandResultValidation.None)
                         .ExecuteAsync(linkedCts.Token);
 
@@ -538,12 +541,20 @@ public class HlsSessionWorker : IHlsSessionWorker
                     {
                         _logger.LogDebug("HLS process has completed for channel {Channel}", _channelNumber);
                         _logger.LogDebug(
-                            "Transcoded until: {Until} - Buffer: {Buffer} seconds",
+                            "Transcoded until: {Until} - Buffer: {Buffer} seconds - Speed {Speed}",
                             processModel.Until,
-                            processModel.Until.Subtract(DateTimeOffset.Now).TotalSeconds);
+                            processModel.Until.Subtract(DateTimeOffset.Now).TotalSeconds,
+                            progressParser.Speed);
                         _transcodedUntil = processModel.Until;
                         _state = NextState(_state, processModel);
                         _hasWrittenSegments = true;
+
+                        progressParser.LogSpeed(
+                            processModel.MediaItemId,
+                            processModel.IsWorkingAhead,
+                            _channelNumber,
+                            _logger);
+
                         return true;
                     }
                     else

ErsatzTV.Application/Streaming/Queries/GetPlayoutItemProcessByChannelNumberHandler.cs

@@ -321,7 +321,7 @@ public class GetPlayoutItemProcessByChannelNumberHandler : FFmpegProcessHandler<
 
             if (request.IsTroubleshooting)
             {
-                channel.Number = ".troubleshooting";
+                channel.Number = FileSystemLayout.TranscodeTroubleshootingChannel;
             }
 
             if (_isDebugNoSync)
@@ -508,7 +508,7 @@ public class GetPlayoutItemProcessByChannelNumberHandler : FFmpegProcessHandler<
 
             if (request.IsTroubleshooting)
             {
-                channel.Number = ".troubleshooting";
+                channel.Number = FileSystemLayout.TranscodeTroubleshootingChannel;
 
                 maybeDuration = TimeSpan.FromSeconds(30);
                 finish = now + TimeSpan.FromSeconds(30);

ErsatzTV.Application/Troubleshooting/Commands/PrepareTroubleshootingPlaybackHandler.cs

@@ -185,7 +185,7 @@ public class PrepareTroubleshootingPlaybackHandler(
         {
             Artwork = [],
             Name = "ETV",
-            Number = ".troubleshooting",
+            Number = FileSystemLayout.TranscodeTroubleshootingChannel,
             FFmpegProfile = ffmpegProfile,
             StreamingMode = request.StreamingMode,
             StreamSelectorMode = ChannelStreamSelectorMode.Troubleshooting,

ErsatzTV.Application/Troubleshooting/Commands/StartTroubleshootingPlaybackHandler.cs

@@ -2,10 +2,10 @@ using System.IO.Pipelines;
 using System.Runtime.InteropServices;
 using System.Text.Json;
 using System.Text.Json.Serialization;
-using System.Text.RegularExpressions;
 using CliWrap;
 using ErsatzTV.Core;
 using ErsatzTV.Core.Domain;
+using ErsatzTV.Core.FFmpeg;
 using ErsatzTV.Core.Interfaces.Locking;
 using ErsatzTV.Core.Interfaces.Streaming;
 using ErsatzTV.Core.Interfaces.Troubleshooting;
@@ -17,7 +17,7 @@ using Serilog.Events;
 
 namespace ErsatzTV.Application.Troubleshooting;
 
-public partial class StartTroubleshootingPlaybackHandler(
+public class StartTroubleshootingPlaybackHandler(
     ITroubleshootingNotifier notifier,
     IMediator mediator,
     IEntityLocker entityLocker,
@@ -138,14 +138,23 @@ public partial class StartTroubleshootingPlaybackHandler(
                         linkedCts.Token);
                 }
 
+                var progressParser = new FFmpegProgress();
+
                 CommandResult commandResult = await processWithPipe
                     .WithWorkingDirectory(FileSystemLayout.TranscodeTroubleshootingFolder)
                     .WithStandardErrorPipe(PipeTarget.Null)
+                    .WithStandardOutputPipe(PipeTarget.ToDelegate(progressParser.ParseLine))
                     .WithValidation(CommandResultValidation.None)
                     .ExecuteAsync(linkedCts.Token);
 
                 logger.LogDebug("Troubleshooting playback completed with exit code {ExitCode}", commandResult.ExitCode);
 
+                progressParser.LogSpeed(
+                    request.MediaItemInfo.Map(i => i.Id),
+                    true,
+                    FileSystemLayout.TranscodeTroubleshootingChannel,
+                    logger);
+
                 try
                 {
                     IEnumerable<string> logs = logService.Sink.GetLogs(request.SessionId);
@@ -160,26 +169,11 @@ public partial class StartTroubleshootingPlaybackHandler(
                     // do nothing
                 }
 
-                Option<double> maybeSpeed =  Option<double>.None;
-                Option<string> maybeFile = Directory.GetFiles(FileSystemLayout.TranscodeTroubleshootingFolder, "ffmpeg*.log").HeadOrNone();
-                foreach (string file in maybeFile)
-                {
-                    await foreach (string line in File.ReadLinesAsync(file, linkedCts.Token))
-                    {
-                        Match match = FFmpegSpeed().Match(line);
-                        if (match.Success && double.TryParse(match.Groups[1].Value, out double speed))
-                        {
-                            maybeSpeed = speed;
-                            break;
-                        }
-                    }
-                }
-
                 await mediator.Publish(
                     new PlaybackTroubleshootingCompletedNotification(
                         commandResult.ExitCode,
                         Option<Exception>.None,
-                        maybeSpeed),
+                        progressParser.Speed),
                     linkedCts.Token);
 
                 if (commandResult.ExitCode != 0)
@@ -210,7 +204,4 @@ public partial class StartTroubleshootingPlaybackHandler(
             loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel = currentStreamingLevel;
         }
     }
-
-    [GeneratedRegex(@"speed=\s*([\d\.]+)x", RegexOptions.IgnoreCase)]
-    private static partial Regex FFmpegSpeed();
 }

ErsatzTV.Core/FFmpeg/FFmpegLibraryProcessService.cs

@@ -576,7 +576,7 @@ public class FFmpegLibraryProcessService : IFFmpegProcessService
             videoVersion.MediaVersion is BackgroundImageMediaVersion { IsSongWithProgress: true },
             false,
             GetTonemapAlgorithm(playbackSettings),
-            channel.Number == ".troubleshooting");
+            channel.Number == FileSystemLayout.TranscodeTroubleshootingChannel);
 
         _logger.LogDebug("FFmpeg desired state {FrameState}", desiredState);
 
@@ -803,7 +803,7 @@ public class FFmpegLibraryProcessService : IFFmpegProcessService
         _logger.LogDebug("HW accel mode: {HwAccel}", hwAccel);
 
         var ffmpegState = new FFmpegState(
-            channel.Number == ".troubleshooting",
+            channel.Number == FileSystemLayout.TranscodeTroubleshootingChannel,
             HardwareAccelerationMode.None, // no hw accel decode since errors loop
             hwAccel,
             VaapiDriverName(hwAccel, vaapiDriver),
@@ -827,7 +827,7 @@ public class FFmpegLibraryProcessService : IFFmpegProcessService
             false,
             false,
             GetTonemapAlgorithm(playbackSettings),
-            channel.Number == ".troubleshooting");
+            channel.Number == FileSystemLayout.TranscodeTroubleshootingChannel);
 
         var ffmpegSubtitleStream = new ErsatzTV.FFmpeg.MediaStream(0, "ass", StreamKind.Video);
 
@@ -851,7 +851,7 @@ public class FFmpegLibraryProcessService : IFFmpegProcessService
             VaapiDisplayName(hwAccel, vaapiDisplay),
             VaapiDriverName(hwAccel, vaapiDriver),
             VaapiDeviceName(hwAccel, vaapiDevice),
-            channel.Number == ".troubleshooting"
+            channel.Number == FileSystemLayout.TranscodeTroubleshootingChannel
                 ? FileSystemLayout.TranscodeTroubleshootingFolder
                 : FileSystemLayout.FFmpegReportsFolder,
             FileSystemLayout.FontsCacheFolder,

ErsatzTV.Core/FFmpeg/FFmpegProgress.cs

@@ -0,0 +1,55 @@
+using System.Text.RegularExpressions;
+using Microsoft.Extensions.Logging;
+
+namespace ErsatzTV.Core.FFmpeg;
+
+public partial class FFmpegProgress
+{
+    public Option<double> Speed { get; private set; } = Option<double>.None;
+
+    public void ParseLine(string line)
+    {
+        Match match = FFmpegSpeed().Match(line);
+        if (match.Success && double.TryParse(match.Groups[1].Value, out double speed))
+        {
+            Speed = speed;
+        }
+    }
+
+    public void LogSpeed(Option<int> mediaItemId, bool isWorkingAhead, string channelNumber, ILogger logger)
+    {
+        foreach (double speed in Speed)
+        {
+            if (isWorkingAhead)
+            {
+                if (speed < 1.0)
+                {
+                    logger.LogCritical(
+                        "Media item {MediaItemId} on channel {Channel} transcoded at {Speed}x (NOT throttled) which is NOT fast enough to support playback",
+                        mediaItemId,
+                        channelNumber,
+                        speed);
+                }
+                else if (speed <= 1.5)
+                {
+                    logger.LogWarning(
+                        "Media item {MediaItemId} on channel {Channel} transcoded at {Speed}x (NOT throttled) which may not be fast enough to support playback",
+                        mediaItemId,
+                        channelNumber,
+                        speed);
+                }
+            }
+            else if (speed < 1.0)
+            {
+                logger.LogWarning(
+                    "Media item {MediaItemId} on channel {Channel} transcoded at {Speed}x (throttled) which may not be fast enough to support playback",
+                    mediaItemId,
+                    channelNumber,
+                    speed);
+            }
+        }
+    }
+
+    [GeneratedRegex(@"speed=\s*([\d\.]+)x", RegexOptions.IgnoreCase)]
+    private static partial Regex FFmpegSpeed();
+}

ErsatzTV.Core/FileSystemLayout.cs

@@ -8,6 +8,7 @@ public static class FileSystemLayout
     public static readonly string AppDataFolder;
 
     public static readonly string TranscodeFolder;
+    public static readonly string TranscodeTroubleshootingChannel;
     public static readonly string TranscodeTroubleshootingFolder;
 
     public static readonly string DataProtectionFolder;
@@ -132,7 +133,8 @@ public static class FileSystemLayout
         }
 
         TranscodeFolder = useCustomTranscodeFolder ? customTranscodeFolder : defaultTranscodeFolder;
-        TranscodeTroubleshootingFolder = Path.Combine(TranscodeFolder, ".troubleshooting");
+        TranscodeTroubleshootingChannel = ".troubleshooting";
+        TranscodeTroubleshootingFolder = Path.Combine(TranscodeFolder, TranscodeTroubleshootingChannel);
 
         DataProtectionFolder = Path.Combine(AppDataFolder, "data-protection");
         LogsFolder = Path.Combine(AppDataFolder, "logs");

ErsatzTV.FFmpeg.Tests/PipelineBuilderBaseTests.cs

@@ -122,7 +122,7 @@ public class PipelineBuilderBaseTests
 
         string command = PrintCommand(videoInputFile, audioInputFile, None, None, None, result);
         command.ShouldBe(
-            "-nostdin -hide_banner -nostats -loglevel error -fflags +genpts+discardcorrupt+igndts -ss 00:00:01 -c:v h264 -readrate 1.05 -i /tmp/whatever.mkv -filter_complex [0:1]aresample=async=1[a] -map 0:0 -map [a] -muxdelay 0 -muxpreload 0 -movflags +faststart -flags cgop -bf 0 -sc_threshold 0 -video_track_timescale 90000 -b:v 2000k -maxrate:v 2000k -bufsize:v 4000k -c:v libx265 -tag:v hvc1 -x265-params log-level=error -c:a aac -b:a 320k -maxrate:a 320k -bufsize:a 640k -ar 48k -f mpegts -mpegts_flags +initial_discontinuity pipe:1");
+            "-nostdin -hide_banner -nostats -loglevel error -fflags +genpts+discardcorrupt+igndts -progress - -ss 00:00:01 -c:v h264 -readrate 1.05 -i /tmp/whatever.mkv -filter_complex [0:1]aresample=async=1[a] -map 0:0 -map [a] -muxdelay 0 -muxpreload 0 -movflags +faststart -flags cgop -bf 0 -sc_threshold 0 -video_track_timescale 90000 -b:v 2000k -maxrate:v 2000k -bufsize:v 4000k -c:v libx265 -tag:v hvc1 -x265-params log-level=error -c:a aac -b:a 320k -maxrate:a 320k -bufsize:a 640k -ar 48k -f mpegts -mpegts_flags +initial_discontinuity pipe:1");
     }
 
     [Test]
@@ -225,7 +225,7 @@ public class PipelineBuilderBaseTests
 
         string command = PrintCommand(videoInputFile, audioInputFile, None, None, None, result);
         command.ShouldBe(
-            "-nostdin -hide_banner -nostats -loglevel error -fflags +genpts+discardcorrupt+igndts -ss 00:00:01 -c:v h264 -readrate 1.05 -i /tmp/whatever.mkv -filter_complex [0:1]aresample=async=1[a] -map 0:0 -map [a] -muxdelay 0 -muxpreload 0 -movflags +faststart -flags cgop -bf 0 -sc_threshold 0 -video_track_timescale 90000 -b:v 2000k -maxrate:v 2000k -bufsize:v 4000k -c:v libx265 -tag:v hvc1 -x265-params log-level=error -c:a aac -ac 6 -b:a 320k -maxrate:a 320k -bufsize:a 640k -ar 48k -f mpegts -mpegts_flags +initial_discontinuity pipe:1");
+            "-nostdin -hide_banner -nostats -loglevel error -fflags +genpts+discardcorrupt+igndts -progress - -ss 00:00:01 -c:v h264 -readrate 1.05 -i /tmp/whatever.mkv -filter_complex [0:1]aresample=async=1[a] -map 0:0 -map [a] -muxdelay 0 -muxpreload 0 -movflags +faststart -flags cgop -bf 0 -sc_threshold 0 -video_track_timescale 90000 -b:v 2000k -maxrate:v 2000k -bufsize:v 4000k -c:v libx265 -tag:v hvc1 -x265-params log-level=error -c:a aac -ac 6 -b:a 320k -maxrate:a 320k -bufsize:a 640k -ar 48k -f mpegts -mpegts_flags +initial_discontinuity pipe:1");
     }
 
     [Test]

ErsatzTV.FFmpeg/GlobalOption/NoStatsOption.cs

@@ -2,5 +2,5 @@
 
 public class NoStatsOption : GlobalOption
 {
-    public override string[] GlobalOptions => new[] { "-nostats" };
+    public override string[] GlobalOptions => ["-nostats"];
 }

ErsatzTV.FFmpeg/GlobalOption/ProgressOption.cs

@@ -0,0 +1,6 @@
+namespace ErsatzTV.FFmpeg.GlobalOption;
+
+public class ProgressOption : GlobalOption
+{
+    public override string[] GlobalOptions => ["-progress", "-"];
+}

ErsatzTV.FFmpeg/Pipeline/PipelineBuilderBase.cs

@@ -220,6 +220,7 @@ public abstract class PipelineBuilderBase : IPipelineBuilder
         if (desiredState.VideoFormat != VideoFormat.Copy)
         {
             pipelineSteps.Add(new ClosedGopOutputOption());
+            pipelineSteps.Add(new ProgressOption());
         }
 
         if (desiredState.VideoFormat != VideoFormat.Copy && !desiredState.AllowBFrames)

ErsatzTV.Infrastructure/Data/Repositories/TemplateDataRepository.cs

@@ -34,7 +34,9 @@ public class TemplateDataRepository(IFileSystem fileSystem, IDbContextFactory<Tv
     {
         try
         {
-            if (channelNumber.Equals(".troubleshooting", StringComparison.OrdinalIgnoreCase))
+            if (channelNumber.Equals(
+                    FileSystemLayout.TranscodeTroubleshootingChannel,
+                    StringComparison.OrdinalIgnoreCase))
             {
                 var now = DateTimeOffset.Now;
                 var topOfHour = new DateTimeOffset(now.Year, now.Month, now.Day, now.Hour, 0, 0, now.Offset);