Extremely slow initialization under the pressure

[snechaev]

Environment

• Package versions:

      <PackageReference Include="FFMpegCore" Version="5.2.0" />
      <PackageReference Include="Instances" Version="3.0.2" />
  

• Net version: 9.0.305
• Target framework: net8.0
• OS: Win11
• ffmpeg version: 7.1.1-full_build-www.gyan.dev

Steps

• Paste the following code snippet into the empty console application. Avoid calling any members of FFMpegCore before this code to prevent static members initialization.

  In this code we emulate the "high" load immediately after the app start.

  using System.Diagnostics;
  using System.Reflection;
  using FFMpegCore;
  using FFMpegCore.Enums;
  
  var dllPath = Assembly.GetExecutingAssembly().Location;
  var dllDir = Path.GetDirectoryName(dllPath)!;
  var binDir = Path.Combine(dllDir, "ffmpeg", "Windows");
  
  GlobalFFOptions.Configure(options =>
  {
      options.BinaryFolder = binDir;
      options.UseCache = true;
  });
  
  var tcs = new TaskCompletionSource<bool>();
  var startSignal = tcs.Task;
  
  //var warmUp = VideoType.Mp4; // <-------------------- uncomment me!!!
  var tasks = Enumerable.Range(0, 20).Select(_ => Task.Run(async () =>
  {
      await startSignal;
      return VideoType.Mp4;
  })).ToList();
  
  var sw = Stopwatch.StartNew();
  tcs.SetResult(true);
  var res = await Task.WhenAll(tasks);
  sw.Stop();
  
  for (var index = 0; index < res.Length; index++)
  {
      var format = res[index];
      Console.WriteLine($"{index} - {format.Extension}");
  }
  Console.WriteLine($"Elapsed: {sw.ElapsedMilliseconds}ms");

• run app and check the time.

In my system this gives Elapsed: 17329ms

Uncomment the line var warmUp = VideoType.Mp4; and run again. I got Elapsed: 2ms

So, when we starting several ffmpeg-related tasks simultaneously, the initialization slows down drastically - x8600 slower.

Workaround

Perform manual initialization of the static members explicitly in the single-threaded mode before running any concurrent tasks. Call this from main thread.

  var warmUp = VideoType.Mp4; 

[snechaev]

Brief research showed that the problem is in the FFMpegCache.ContainerFormats.get - the most time is spend here on the locks.

[snechaev]

Looks like the thread pool starvation: 19 threads are locked inside the FFMpegCache.ContainerFormats.get.
I tested this hypothesis in this way:

ThreadPool.GetMinThreads(out var x, out var y);
ThreadPool.SetMinThreads(Math.Max(x, 25), y);

and got the 410ms instead of 17329ms.

[snechaev]

a more real-life example: just run multiply (50) tasks with a SnapshotAsync. And this will take a looot of time.

GlobalFFOptions.Configure(options =>
{
    options.BinaryFolder = binDir;
    options.UseCache = true;
});

var mp4 = @"D:\delme\TestData\Photo\test.mp4";
var tasks = Enumerable.Range(0, 50).Select(x => Task.Run(async () =>
{
    var tempThumbnailPath = Path.GetTempFileName();
    tempThumbnailPath = Path.ChangeExtension(tempThumbnailPath, ".png");
    await FFMpeg.SnapshotAsync(mp4, tempThumbnailPath, captureTime: TimeSpan.FromSeconds(2)).ConfigureAwait(false);
    return tempThumbnailPath;
})).ToList();

var res = await Task.WhenAll(tasks).ConfigureAwait(false);
foreach (var r in res)
{
    Console.WriteLine(r);
}

What is going one here? Somewhere in the middle of the process we have the following tasks graph:

Here we can see that 41 logical stacks is synchronously blocked on the Process.WaitForExit()

So, the sequence is following

• we start a bunch of tasks simultaneously.
• the tasks began to work on available thread pool threads and consume all the threads.
• as we have no cached results of the VerifyFFProbeExists call, each task runs the ffprobe.exe -version and began to wait for the execution results synchronously using _process.WaitForExit();. This blocks all the available threads in thread pool (see the top-left part of the diagram - 41 logical stacks is synchronously blocked inside the Process.WaitForExit()).
  • when starting the process, we use EnableRaisingEvents=true and asynchronous I/O (OutputDataReceived, ErrorDataReceived events) to work with a stdout/stderr redirection.
  • current implementation of this asynchronous I/O uses System.Diagnostics.AsyncStreamReader.ReadBufferAsync() internally (see bottom-center of the diagram). This code internally relies on the Tasks and the thread pool.
  • as all the thread pool thread are blocked, AsyncStreamReader.ReadBufferAsync() can't read anything (corresponding tasks are scheduled, but there are no threads available in thread pool to execute them).
  • as the stdout & stderr are not read, the process continue to "work" and process.WaitForExit() will not return and unblock threads.
• at the some moment thread pool realizes that all the threads are busy and adds the new thread (if not hit the limits)
  • important. If the thread pool won't grow due to ThreadPool.SetMaxThreads()-limits or due to other reasons, the whole application will hang.
• the next SnapshotAsync() task starts to execute on this new thread and immediately block it.
• thread pool slowly grows more and more and at the some point it has more threads, then we have SnapshotAsync() tasks (50 in our sample). At this moment we have the free thread to handle tasks for the AsyncStreamReader.
• this will finally cause the process.WaitForExit() to return and unblock a lot of additional threads in the thread pool and further processing can do the work.
• theoretically, after the VerifyFFProbeExists bottleneck is passed, the process can stack in the same way again on the VerifyFFMpegExists.

Possible workaround

We can run the following code to fill all the caches, perform checks and cache its results.

void WarmUp()
{
    FFProbeHelper.VerifyFFProbeExists(GlobalFFOptions.Current);
    FFMpegHelper.VerifyFFMpegExists(GlobalFFOptions.Current);
    FFMpeg.GetCodecs();
    FFMpeg.GetContainerFormats();
    FFMpeg.GetPixelFormats();
}

Honestly, this is a dirty hack because it is strictly relates on the knowledge of the implementation details and other internals of the FFMpegCore and BCL. Therefore, it could stop working at any time, so I can't recommend using it in production.

Possible way to fix

Looks like the only reliable way to fix this is to completely remove the synchronous blocking operations from the async versions of the API. For example, by replacing with the async-friendly versions. This includes at least the following

• VerifyFFProbeExists
• VerifyFFMpegExists
• GetCodecsInternal
• GetContainersFormatsInternal
• GetPixelFormatsInternal

Alternatively, the some kind of warm-up function can be included in the FFMpegCore code (so it will encapsulate all the knowledge of the implementation details to fill caches/verify binaries/etc) and call it during the initialization in the single thread manner (automatically or manually).

[ememadegbola]

+1
Great work diagnosing this. I've been running into the same issue for a few weeks (attempting to run multiple probes and encodes immediately on application start) and couldn't figure out where the slowdown was.
I've applied the WarmUp method workaround and it has drastically sped things up, similar to your results.
Would be nice to have an official fix though, as you say the workaround is too dependent on implementation details