Search code examples
async-await.net-5parallel.foreachilogger

Using ILogger in parallel


In the following code, the program terminates before the log has been fully flushed:

    class Program
    {
      static void Main(string[] args)
      {
        var count = -1;
        var tasks = new ConcurrentBag<Task>();

        var services = new ServiceCollection();
        services.AddLogging(configure => configure.AddConsole());
        var serviceProvider = services.BuildServiceProvider();
        var logger = serviceProvider.GetService<ILogger<Program>>();
        if (logger is null)
          throw new NullReferenceException();

        Parallel.ForEach(Enumerable.Range(0, 1000), i =>
        {
          tasks.Add(Task.Run(() => logger.LogInformation(Interlocked.Increment(ref count).ToString())));
          //tasks.Add(Task.Run(() => Console.WriteLine(Interlocked.Increment(ref count).ToString())));
        });

        Task.WhenAll(tasks).Wait();
      }
    }

Even though 1.000 log statements should be printed, only the following is flushed:

info: Net5.Program[0]
      6
info: Net5.Program[0]
      2
info: Net5.Program[0]
      5
info: Net5.Program[0]
      1
info: Net5.Program[0]
      7
info: Net5.Program[0]
      4
info: Net5.Program[0]
      3
info: Net5.Program[0]
      0
info: Net5.Program[0]
      8
info: Net5.Program[0]
      10

C:\Users\MyName\source\repos\ConsoleApp\Net5\bin\Debug\net5.0\Net5.exe (process 28048) exited with code 0.
Press any key to close this window . . .

When using Console.WriteLine (commented out in the code above), however, all lines are printed, which leads be to suspect that the console logger is asynchronous behind the scenes.

How can I ensure that all log statements are awaited without resorting to a manual delay?

Edit:

I settled on the following code, which did the trick:

class Program
{
  static void Main(string[] args)
  {
    var count = -1;

    var services = new ServiceCollection();
    services.AddLogging(configure => configure.AddConsole());
    using var serviceProvider = services.BuildServiceProvider();
    var logger = serviceProvider.GetRequiredService<ILogger<Program>>();

    var tasks = Enumerable.Range(0, 50000)
      .AsParallel()
      .Select(_ => Task.Run(() => logger.LogInformation(Interlocked.Increment(ref count).ToString())));

    Task.WhenAll(tasks).Wait();
  }
}

Key differences:

  • Service Provider is disposed, which fixed the log flushing issue.
  • Get ILogger instance by using GetRequiredService to avoid having to null check.
  • Use Enumerable.Range(...).AsParallel.Select(...) instead of Parallel.ForEach to stick with Tasks all the way.

Solution

  • If you dispose of the service provider, it will dispose of all singleton services and that will flush the logger.

    There's also no need to use Parallel.ForEach. In fact, using Parallel.ForEach with async`await` is a code smell. It's almost always wrong.

    And, since you tagged the question .NET 5.0, you can change your code to:

    class Program
    {
        static async Task Main()
        {
            var count = -1;
            var tasks = new ConcurrentBag<Task>();
    
            var services = new ServiceCollection();
            services.AddLogging(configure => configure.AddConsole());
            using var serviceProvider = services.BuildServiceProvider();
            var logger = serviceProvider.GetRequiredService<ILogger<Program>>();
    
            for (var i = 0; i < 1000; i++)
            {
                tasks.Add(Task.Run(() => logger.LogInformation(Interlocked.Increment(ref count).ToString())));
            };
    
            await Task.WhenAll(tasks);
        }
    }