Developers using ILogger have improved performance

[sebastienros]

Improve performance characteristics of Logging.

Areas of interest:

• Improve Console logging performance
• Minimize impact of no-op logging (without requiring to clear providers)
• Define percentage overhead for logging providers

Issues:

• Logging-Generator should allow to skip the IsEnabled check #51927 - Logging-Generator should allow to skip the IsEnabled check
• Fix the boxing when using the LoggerMessage.Define is used and values are converted ToString #50768 - Fix the boxing when using the LoggerMessage.Define is used and values are converted ToString

[sebastienros]

dotnet/aspnetcore#29620 (comment)

[sebastienros]

TODO: Add Fortunes/EF/MVC/HTTPS scenario with loggers turned on (nothing logged) and re-enable Json Middleware with logging.

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Improve performance characteristics of Logging.

Areas of interest:

• Improve Console logging performance
• Minimize impact of no-op logging (without requiring to clear providers)
• Define percentage overhead for logging providers

Author:	sebastienros
Assignees:	davidfowl
Labels:	area-Extensions-Logging, untriaged
Milestone:	-

[maryamariyan]

Minimize impact of no-op logging (without requiring to clear providers)

Here's an isolated benchmark for no-op vs disabled use case: (I had to loop 1000 times for a proper diff to show up between the two cases)

For benchmarks

        [Benchmark]
        public void LogDebug()
        {
            for (int i = 0; i < 1000; i++)
                _logger.LogDebug(@"Connection id '{connectionId}', range [{start}..{end}], options {options}", ConnectionId, Start, End, Options);
        }


        [Benchmark]
        public void LoggerMessage()
        {
            for (int i = 0; i < 1000; i++)
                _loggerMessage2(_logger, ConnectionId, Start, End, Options, null);
        }

where loggerMessage2 is:

        private static Action<ILogger, string, long, long, int, Exception?> _loggerMessage2 = LoggerMessage.Define<string, long, long, int>(LogLevel.Debug,
                            eventId: 381,
                            formatString: @"Connection id '{connectionId}', range [{start}..{end}], options {options}");

and _logger as ConsoleLogger,

Using

// noop (logger.IsEnabled(LogLevel.Debug) will be false here)
                .AddLogging(logBuilder =>
                {
                    logBuilder.AddConsole().SetMinimumLevel(LogLevel.Information);
                })

We get

|            Method |      Mean |    Error |   StdDev |   Gen 0 | Gen 1 | Gen 2 | Allocated |
|------------------ |----------:|---------:|---------:|--------:|------:|------:|----------:|
|          LogDebug | 143.60 us | 2.859 us | 7.225 us | 16.1133 |     - |     - |  128000 B |
|     LoggerMessage |  11.36 us | 0.226 us | 0.338 us |       - |     - |     - |         - |

and using

// disabled
                .AddLogging(logBuilder =>
                {
                    logBuilder.ClearProviders();
                })

we get:

|            Method |       Mean |     Error |    StdDev |   Gen 0 | Gen 1 | Gen 2 | Allocated |
|------------------ |-----------:|----------:|----------:|--------:|------:|------:|----------:|
|          LogDebug | 137.765 us | 2.7482 us | 7.0939 us | 16.1133 |     - |     - |  128000 B |
|     LoggerMessage |   9.170 us | 0.2059 us | 0.6007 us |       - |     - |     - |         - |

link to gist

Here's another perf report using Microsoft.Crank: https://gist.github.com/maryamariyan/06370e90cdc7809037de59a88662d9d6

Define percentage overhead for logging providers

These benchmarks show there is definitely a perf overhead with adding logging providers

[maryamariyan]

I added more benchmarks and a little report with a set of logging use cases here: https://gist.github.com/maryamariyan/0bad4136655f344bf203274e5b7431b4

cc: @gfoidl @adamsitnik @davidfowl @sebastienros