Benchmarks for system vs logging for console

README_1024Limit.md

Using cmd:

|                   Method |     Mean |    Error |   StdDev | Allocated |
|------------------------- |---------:|---------:|---------:|----------:|
|   LoggingConsole_OneChar | 182.4 us |  4.98 us | 14.69 us |     185 B |
|    SystemConsole_OneChar | 182.1 us |  5.71 us | 16.74 us |         - |
|   LoggingConsole_10Chars | 183.4 us |  4.07 us | 11.87 us |     214 B |
|    SystemConsole_10Chars | 183.0 us |  4.75 us | 13.92 us |         - |
|  LoggingConsole_100Chars | 184.6 us |  4.85 us | 13.99 us |     394 B |
|   SystemConsole_100Chars | 194.1 us |  4.38 us | 12.70 us |         - |
| LoggingConsole_1000Chars | 530.2 us | 10.60 us | 28.12 us |   2,171 B |
|  SystemConsole_1000Chars | 542.6 us | 10.42 us | 30.22 us |         - |

Consider 530.2us for 1000 chars. That is 1886 iterations per second for 1000 chars per iteration (2000 bytes per iteration), which is 3.6 MB/sec. Now comparing this BenchmarkDotNet speed for console logging to just using a StopWatch in a console app:

       using var loggerFactory = LoggerFactory.Create(builder =>
        {
            builder.AddCustomFormatter(o =>
                o.CustomPrefix = " ~~~~~ ");
        });

        var logger = loggerFactory.CreateLogger<Program>();
        var sw = new Stopwatch();
        sw.Start();
        for (int i = 0; i < 10000; i++)
        {
            logger.LogInformation(_1000Chars);
        }
        sw.Stop();
        var elapsedForLoggingConsole = sw.ElapsedMilliseconds;

        Console.Error.WriteLine($"how many bytes? {howManyBytes} * 10000 = {howManyBytes * 10000} = {howManyBytes * 10000 / (1024 * 1024)}MB");
        Console.Error.WriteLine($"elapsedForLoggingConsole: {elapsedForLoggingConsole}ms");
        Console.Error.WriteLine($"Speed: {(howManyBytes * 10000 / (1024 * 1024)) / (elapsedForLoggingConsole / 1000.0f)} MB/sec");

Output

how many bytes? 2000 * 10000 = 20000000 = 19MB
elapsedForLoggingConsole: 3827ms
Speed: 4.9647245MB/sec

Same experiment now for Console.WriteLine:

        var howManyBytes = _1000Chars.Length * sizeof(char);
        var sw = new Stopwatch();
        sw.Start();
        for (int i = 0; i < 10000; i++)
        {
            Console.WriteLine(_1000Chars);
        }
        sw.Stop();
        var elapsedForSystemConsole = sw.ElapsedMilliseconds;
        Console.Error.WriteLine($"how many bytes? {howManyBytes} * 10000 = {howManyBytes * 10000} = {howManyBytes * 10000 / (1024 * 1024)}MB");
        Console.Error.WriteLine($"elapsedForSystemConsole: {elapsedForSystemConsole}ms");
        Console.Error.WriteLine($"Speed: {(howManyBytes * 10000 / (1024 * 1024)) / (elapsedForSystemConsole / 1000.0f)} MB/sec");

Output

how many bytes? 2000 * 10000 = 20000000 = 19MB
elapsedForSystemConsole: 4365ms
Speed: 4.3528066MB/sec

Also note, the logging console speed increases significantly with the output piped to a file output:

> dotnet run -c Release 
...

how many bytes? 2000 * 10000 = 20000000 = 19MB
elapsedForLoggingConsole: 3773ms
Speed: 5.0357804 MB/sec

> dotnet run -c Release > out.txt

how many bytes? 2000 * 10000 = 20000000 = 19MB
elapsedForLoggingConsole: 175ms
Speed: 108.571434 MB/sec

> dotnet run -c Release > nul

how many bytes? 2000 * 10000 = 20000000 = 19MB
elapsedForLoggingConsole: 39ms
Speed: 487.17947 MB/sec

README_NoCache.md

With _maxQueuedMessages removed from ConsoleLoggerProcessor, using cmd:

|                   Method |     Mean |    Error |   StdDev | Allocated |
|------------------------- |---------:|---------:|---------:|----------:|
|   LoggingConsole_OneChar | 174.1 us |  5.73 us | 16.81 us |     176 B |
|    SystemConsole_OneChar | 177.5 us |  4.55 us | 13.34 us |         - |
|   LoggingConsole_10Chars | 182.3 us |  4.46 us | 13.16 us |     210 B |
|    SystemConsole_10Chars | 184.0 us |  4.06 us | 11.91 us |         - |
|  LoggingConsole_100Chars | 190.2 us |  3.77 us |  9.02 us |     393 B |
|   SystemConsole_100Chars | 193.0 us |  3.80 us |  6.45 us |         - |
| LoggingConsole_1000Chars | 509.4 us | 10.06 us | 10.33 us |   2,183 B |
|  SystemConsole_1000Chars | 540.4 us | 12.51 us | 36.90 us |         - |

contention-experiment.md

Locally updated logging console dll to produce counter mel.c.q to show the blocking collection queue count on high load.

With only 10000 as the loop count on windows:

        for (int i = 0; i < 10000; i++)
        {
            logger.LogInformation(_1000Chars);
        }

The counters show that the collection would reach 1024 max size, and there is lock contention as well.

Next, with the max size increase to a larger number 100,000 arbitrarily, we no longer get the lock contention and the speed goes up from 5.14 MB/sec to 790 MB/sec.

loop-compare.md

|                 Method |    Mean |  Error | StdDev |      Gen 0 |      Gen 1 |     Allocated |
|----------------------- |--------:|-------:|-------:|-----------:|-----------:|--------------:|
| LoggingConsole_OneChar | 175.7 s | 3.35 s | 4.24 s | 59000.0000 | 53000.0000 | 236,966,592 B |
|  SystemConsole_OneChar | 175.0 s | 2.00 s | 1.87 s | 63000.0000 | 63000.0000 |         696 B |

        [Benchmark]
        public void LoggingConsole_OneChar()
        {
            for (int i = 0; i < 1000000; i++)
            {
                _logger.LogInformation("a");
            }
        }

        [Benchmark]
        public void SystemConsole_OneChar()
        {
            for (int i = 0; i < 1000000; i++)
            {
                Console.WriteLine("a");
            }
        }

Program.cs

using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Logging.Console;
using Microsoft.Extensions.Options;

namespace Benchmark
{
    public class Program
    {
        public static void Main()
        {
            var summary = BenchmarkRunner.Run<LogBenchmark>();
        }
    }

    [MemoryDiagnoser]
    public class LogBenchmark
    {
        private ILogger<Program> _logger;
        private ILoggerFactory _loggerFactory;
        private string _1000Chars = new string('a', 1000);
        private string _100Chars = new string('a', 100);
        private string _10Chars = new string('a', 10);

        [GlobalSetup]
        public void SetupBasic()
        {
            _loggerFactory = LoggerFactory.Create(builder =>
            {
                builder.AddSimpleConsole(o =>
                {
                    o.ColorBehavior = LoggerColorBehavior.Disabled;
                    o.TimestampFormat = "hh:mm:ss";
                    o.SingleLine = true;
                }).AddCustomFormatter(o =>
                    o.CustomPrefix = " ~~~~~ ");
            });

            _logger = _loggerFactory.CreateLogger<Program>();
        }

        [GlobalCleanup]
        public void CleanupBasic()
        {
            _loggerFactory.Dispose();
        }

        [Benchmark]
        public void LoggingConsole_OneChar() => _logger.LogInformation("a");

        [Benchmark]
        public void SystemConsole_OneChar() => Console.WriteLine("a");

        [Benchmark]
        public void LoggingConsole_10Chars() => _logger.LogInformation(_10Chars);

        [Benchmark]
        public void SystemConsole_10Chars() => Console.WriteLine(_10Chars);

        [Benchmark]
        public void LoggingConsole_100Chars() => _logger.LogInformation(_100Chars);

        [Benchmark]
        public void SystemConsole_100Chars() => Console.WriteLine(_100Chars);

        [Benchmark]
        public void LoggingConsole_1000Chars() => _logger.LogInformation(_1000Chars);

        [Benchmark]
        public void SystemConsole_1000Chars() => Console.WriteLine(_1000Chars);
    }
    public static class ConsoleLoggerExtensions
    {
        public static ILoggingBuilder AddCustomFormatter(
            this ILoggingBuilder builder,
            Action<CustomOptions> configure) =>
            builder.AddConsole(options => options.FormatterName = "customName")
                .AddConsoleFormatter<CustomFormatter, CustomOptions>(configure);
    }
    public class CustomOptions : ConsoleFormatterOptions
    {
        public string? CustomPrefix { get; set; }
    }

    public sealed class CustomFormatter : ConsoleFormatter, IDisposable
    {
        private readonly IDisposable _optionsReloadToken;
        private CustomOptions _formatterOptions;

        public CustomFormatter(IOptionsMonitor<CustomOptions> options)
            // Case insensitive
            : base("customName") =>
            (_optionsReloadToken, _formatterOptions) =
                (options.OnChange(ReloadLoggerOptions), options.CurrentValue);

        private void ReloadLoggerOptions(CustomOptions options) =>
            _formatterOptions = options;

        public override void Write<TState>(
            in LogEntry<TState> logEntry,
            IExternalScopeProvider scopeProvider,
            TextWriter textWriter)
        {
            string? message =
                logEntry.Formatter?.Invoke(
                    logEntry.State, logEntry.Exception);

            if (message is null)
            {
                return;
            }

            // CustomLogicGoesHere(textWriter);
            textWriter.WriteLine(message);
        }

        private void CustomLogicGoesHere(TextWriter textWriter)
        {
            textWriter.Write(_formatterOptions.CustomPrefix);
        }

        public void Dispose() => _optionsReloadToken?.Dispose();
    }
}

when profiling for:

        for (int i = 0; i < 10000; i++)
        {
            logger.LogInformation("10:44:31info: Program[0] LogInformation information");
        }