Skip to content

Instantly share code, notes, and snippets.

@maryamariyan
Last active May 20, 2021 18:18
Show Gist options
  • Save maryamariyan/0bad4136655f344bf203274e5b7431b4 to your computer and use it in GitHub Desktop.
Save maryamariyan/0bad4136655f344bf203274e5b7431b4 to your computer and use it in GitHub Desktop.
Benchmarks on Logging
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<TargetFrameworks>net6.0</TargetFrameworks>
<MicrosoftExtensionsVersion Condition="'$(TargetFramework)' == 'net6.0'">6.0.0-preview.6.21269.7</MicrosoftExtensionsVersion>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="BenchmarkDotNet" Version="0.12.1" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="$(MicrosoftExtensionsVersion)" />
<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="$(MicrosoftExtensionsVersion)" />
</ItemGroup>
</Project>
using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Runtime.CompilerServices;
using Microsoft.Extensions.Logging;
namespace Benchmark
{
public class MockLogger : ILogger
{
public IDisposable BeginScope<TState>(TState state) => throw new NotImplementedException();
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
=> LogCore(formatter(state, exception));
[MethodImpl(MethodImplOptions.NoInlining)]
private static void LogCore(string _) { }
}
public class CustomProvider : ILoggerProvider
{
public ILogger CreateLogger(string categoryName) => new MockLogger();
public void Dispose() { }
}
}
using Benchmark;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;
using Microsoft.Extensions.Logging;
using System;
#nullable enable
namespace BenchmarkForLogXApis
{
public static partial class Program
{
public static void Main(string[] args)
{
_ = BenchmarkSwitcher.FromAssembly(typeof(LogBenchmark).Assembly).Run(args);
}
private static partial class Log
{
private static readonly Action<ILogger, string, int, string, int, long, Exception?> s_log_warning_5args_skipEnabledCheck_false = LoggerMessage.Define<string, int, string, int, long>(
LogLevel.Warning,
new EventId(1003),
MessageTemplate_5_Args);
private static readonly Action<ILogger, string, int, string, int, long, Exception?> s_log_warning_5args_skipEnabledCheck_true = LoggerMessage.Define<string, int, string, int, long>(
LogLevel.Warning,
new EventId(1004),
MessageTemplate_5_Args,
skipEnabledCheck: true);
private static readonly Action<ILogger, Exception?> s_log_critical_0args_skipEnabledCheck_false = LoggerMessage.Define(
LogLevel.Critical,
new EventId(1005),
MessageTemplate_0_Args);
private static readonly Action<ILogger, Exception?> s_log_critical_0args_skipEnabledCheck_true = LoggerMessage.Define(
LogLevel.Critical,
new EventId(1006),
MessageTemplate_0_Args,
skipEnabledCheck: true);
private static readonly Action<ILogger, string, int, Exception?> s_log_critical_2args_skipEnabledCheck_false = LoggerMessage.Define<string, int>(
LogLevel.Critical,
new EventId(1007),
MessageTemplate_2_Args);
private static readonly Action<ILogger, string, int, Exception?> s_log_critical_2args_skipEnabledCheck_true = LoggerMessage.Define<string, int>(
LogLevel.Critical,
new EventId(1008),
MessageTemplate_2_Args,
skipEnabledCheck: true);
private static readonly Action<ILogger, string, int, string, int, long, Exception?> s_log_critical_5args_skipEnabledCheck_false = LoggerMessage.Define<string, int, string, int, long>(
LogLevel.Critical,
new EventId(1009),
MessageTemplate_5_Args);
private static readonly Action<ILogger, string, int, string, int, long, Exception?> s_log_critical_5args_skipEnabledCheck_true = LoggerMessage.Define<string, int, string, int, long>(
LogLevel.Critical,
new EventId(1010),
MessageTemplate_5_Args,
skipEnabledCheck: true);
public static void LogWarning_5args_skipEnabledCheck_false(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts) => s_log_warning_5args_skipEnabledCheck_false(logger, name, age, city, yearsSince, numDonuts, null);
public static void LogWarning_5args_skipEnabledCheck_true(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts) => s_log_warning_5args_skipEnabledCheck_true(logger, name, age, city, yearsSince, numDonuts, null);
public static void LogCritical_0args_skipEnabledCheck_false(ILogger logger) => s_log_critical_0args_skipEnabledCheck_false(logger, null);
public static void LogCritical_0args_skipEnabledCheck_true(ILogger logger) => s_log_critical_0args_skipEnabledCheck_true(logger, null);
public static void LogCritical_2args_skipEnabledCheck_false(ILogger logger, string name, int age) => s_log_critical_2args_skipEnabledCheck_false(logger, name, age, null);
public static void LogCritical_2args_skipEnabledCheck_true(ILogger logger, string name, int age) => s_log_critical_2args_skipEnabledCheck_true(logger, name, age, null);
public static void LogCritical_5args_skipEnabledCheck_false(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts) => s_log_critical_5args_skipEnabledCheck_false(logger, name, age, city, yearsSince, numDonuts, null);
public static void LogCritical_5args_skipEnabledCheck_true(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts) => s_log_critical_5args_skipEnabledCheck_true(logger, name, age, city, yearsSince, numDonuts, null);
}
private const string MessageTemplate_0_Args = "message template #0: Name Batman is 82 years old from Gotham moved here 2 years ago bought 20 donuts";
private const string MessageTemplate_2_Args = "message template #0: Name {Name} is {Age} years old from Gotham moved here 2 years ago bought 20 donuts";
private const string MessageTemplate_5_Args = "message template #0: Name {Name} is {Age} years old from {City} moved here {YearsSince} years ago bought {numDonuts} donuts";
[LoggerMessage(EventId = 1022, Level = LogLevel.Warning, Message = MessageTemplate_5_Args)]
public static partial void LogWarning_5args_Generated(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts);
[LoggerMessage(EventId = 1023, Level = LogLevel.Critical, Message = MessageTemplate_0_Args)]
public static partial void LogCritical_0args_Generated(ILogger logger);
[LoggerMessage(EventId = 1024, Level = LogLevel.Critical, Message = MessageTemplate_2_Args)]
public static partial void LogCritical_2args_Generated(ILogger logger, string name, int age);
[LoggerMessage(EventId = 1025, Level = LogLevel.Critical, Message = MessageTemplate_5_Args)]
public static partial void LogCritical_5rgs_Generated(ILogger logger, string name, int age, string city, int yearsSince, long numDonuts);
private static int MaxCachedFormatters = 1024;
private static string Name = "Batman";
private static int Age = 82;
private static string City = "Gotham";
private static int YearsSince = 2;
private static long NumDonuts = 20;
private static int NumLoggerProviders = 7;
private static int NumExtraLoggers = 0;
[MemoryDiagnoser]
[DisassemblyDiagnoser]
public partial class LogBenchmark
{
private readonly string[] _messageTemplates;
private readonly ILogger loggerFromClearedProviders, loggerFromOneMockProvider, loggerFrom7MockProvidersMinLevelCritical, loggerFrom10MockProviders, loggerFrom3MockProviders;
public LogBenchmark()
{
loggerFrom10MockProviders = SetupLogger(builder =>
{
builder.ClearProviders();
for (int i = 0; i < 10; i++)
builder.AddProvider(new CustomProvider());
builder.SetMinimumLevel(LogLevel.Critical);
}, category: nameof(loggerFrom10MockProviders), NumExtraLoggers);
loggerFrom3MockProviders = SetupLogger(builder =>
{
builder.ClearProviders();
for (int i = 0; i < 3; i++)
builder.AddProvider(new CustomProvider());
builder.SetMinimumLevel(LogLevel.Critical);
}, category: nameof(loggerFrom3MockProviders), NumExtraLoggers);
loggerFromOneMockProvider = SetupLogger(builder =>
{
builder.ClearProviders();
builder.AddProvider(new CustomProvider());
builder.SetMinimumLevel(LogLevel.Critical);
}, category: nameof(loggerFromOneMockProvider), NumExtraLoggers);
loggerFromClearedProviders = SetupLogger(builder =>
{
builder.ClearProviders();
builder.SetMinimumLevel(LogLevel.Critical);
}, category: nameof(loggerFromClearedProviders), NumExtraLoggers);
loggerFrom7MockProvidersMinLevelCritical = SetupLoggerFrom7MockProvidersMinLevelCritical(NumLoggerProviders, NumExtraLoggers, category: nameof(loggerFrom7MockProvidersMinLevelCritical));
if (!loggerFrom7MockProvidersMinLevelCritical.IsEnabled(LogLevel.Critical))
{
throw new InvalidOperationException("bad setup");
}
// LogCritical with 1024 different message templates to trigger scenario for max number of cached formatters
_messageTemplates = new string[MaxCachedFormatters + 1];
for (int i = 0; i < _messageTemplates.Length; i++)
{
_messageTemplates[i] = $"message template #{i}: " + "Name {Name} is {Age} years old from {City} moved here {YearsSince} years ago bought {numDonuts} donuts";
loggerFrom7MockProvidersMinLevelCritical.LogCritical(_messageTemplates[i], Name, Age, City, YearsSince, NumDonuts);
}
}
private static ILogger SetupLogger(Action<ILoggingBuilder> configure, string category, int numExtraLoggers)
{
ILoggerFactory tempFactory = LoggerFactory.Create(configure);
for (int i = 0; i < numExtraLoggers; i++)
{
tempFactory.CreateLogger(i.ToString());
}
return tempFactory.CreateLogger(category);
}
private static ILogger SetupLoggerFrom7MockProvidersMinLevelCritical(int numLoggerProviders, int numExtraLoggers, string category)
{
ILoggerFactory tempFactory = LoggerFactory.Create(
builder =>
{
builder.ClearProviders();
for (int i = 0; i < numLoggerProviders; i++)
builder.AddProvider(new CustomProvider());
builder.SetMinimumLevel(LogLevel.Critical);
});
for (int i = 0; i < numExtraLoggers; i++)
{
tempFactory.CreateLogger(i.ToString());
}
return tempFactory.CreateLogger(category);
}
[Benchmark]
public void Log_LogWarning_IsEnabledIfCheck_NotAdded_LogNotEnabled_0_Providers()
{
// [A] If using LogWarning/LogInformation/etc. then guard the call against ILogger.IsEnabled(level) to avoid unnecessary allocation when logging is disabled for that level.
// Even in the case where we've cleared providers we get reduced perf and allocations
// Consider using LoggerMessage.Define APIs instead
loggerFromClearedProviders.LogWarning(MessageTemplate_5_Args, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LogWarning_IsEnabledIfCheck_Added_LogNotEnabled_0_Providers()
{
// [A] If using LogWarning/LogInformation/etc. then guard the call against ILogger.IsEnabled(level) to avoid unnecessary allocation when logging is disabled for that level.
// Even in the case where we've cleared providers we get reduced perf and allocations
// Consider using LoggerMessage.Define APIs instead
if (loggerFromClearedProviders.IsEnabled(LogLevel.Warning))
{
loggerFromClearedProviders.LogWarning(MessageTemplate_5_Args, Name, Age, City, YearsSince, NumDonuts);
}
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_0args_LogEnabled_01_Provider() => Log.LogCritical_0args_skipEnabledCheck_false(loggerFromOneMockProvider);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_01_Provider() => Log.LogCritical_0args_skipEnabledCheck_true(loggerFromOneMockProvider);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_01_Provider_Generated() => LogCritical_0args_Generated(loggerFromOneMockProvider);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_2args_LogEnabled_01_Provider() => Log.LogCritical_2args_skipEnabledCheck_false(loggerFromOneMockProvider, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_01_Provider() => Log.LogCritical_2args_skipEnabledCheck_true(loggerFromOneMockProvider, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_01_Provider_Generated() => LogCritical_2args_Generated(loggerFromOneMockProvider, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_01_Provider() => Log.LogCritical_5args_skipEnabledCheck_false(loggerFromOneMockProvider, Name, Age, City, YearsSince, NumDonuts);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_01_Provider() => Log.LogCritical_5args_skipEnabledCheck_true(loggerFromOneMockProvider, Name, Age, City, YearsSince, NumDonuts);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_01_Provider_Generated() => LogCritical_5rgs_Generated(loggerFromOneMockProvider, Name, Age, City, YearsSince, NumDonuts);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_0args_LogEnabled_10_Provider() => Log.LogCritical_0args_skipEnabledCheck_false(loggerFrom10MockProviders);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_10_Provider() => Log.LogCritical_0args_skipEnabledCheck_true(loggerFrom10MockProviders);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_10_Provider_Generated() => LogCritical_0args_Generated(loggerFrom10MockProviders);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_2args_LogEnabled_10_Provider() => Log.LogCritical_2args_skipEnabledCheck_false(loggerFrom10MockProviders, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_10_Provider() => Log.LogCritical_2args_skipEnabledCheck_true(loggerFrom10MockProviders, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_10_Provider_Generated() => LogCritical_2args_Generated(loggerFrom10MockProviders, Name, Age);
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_10_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_false(loggerFrom10MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_10_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_true(loggerFrom10MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_10_Providers_Generated()
{
LogCritical_5rgs_Generated(loggerFrom10MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_03_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_false(loggerFrom3MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_03_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_true(loggerFrom3MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_03_Providers_Generated()
{
LogCritical_5rgs_Generated(loggerFrom3MockProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_07_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_false(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_07_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_true(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_07_Providers_Generated()
{
LogCritical_5rgs_Generated(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogNotEnabled_07_Providers()
{
Log.LogWarning_5args_skipEnabledCheck_false(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogNotEnabled_07_Providers()
{
// [C] when using Skip check, make sure to always add the isEnabled check otherwise, you get bad perf when log level not enabled
if (loggerFrom7MockProvidersMinLevelCritical.IsEnabled(LogLevel.Warning))
{
Log.LogWarning_5args_skipEnabledCheck_true(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogNotEnabled_07_Providers_Generated()
{
// [C] when using Skip check, make sure to always add the isEnabled check otherwise, you get bad perf when log level not enabled
if (loggerFrom7MockProvidersMinLevelCritical.IsEnabled(LogLevel.Warning))
{
LogWarning_5args_Generated(loggerFrom7MockProvidersMinLevelCritical, Name, Age, City, YearsSince, NumDonuts);
}
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_00_Providers()
{
Log.LogCritical_5args_skipEnabledCheck_false(loggerFromClearedProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_00_Providers()
{
if (loggerFromClearedProviders.IsEnabled(LogLevel.Critical))
Log.LogCritical_5args_skipEnabledCheck_true(loggerFromClearedProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark]
public void Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_00_Providers_Generated()
{
if (loggerFromClearedProviders.IsEnabled(LogLevel.Critical))
LogCritical_5rgs_Generated(loggerFromClearedProviders, Name, Age, City, YearsSince, NumDonuts);
}
[Benchmark(OperationsPerInvoke = 5)]
public void LogCritical_CachedFormatter_Used_LogEnabled_07_Providers()
{
if (loggerFrom7MockProvidersMinLevelCritical.IsEnabled(LogLevel.Critical))
{
// [B] If using LogWarning/LogInformation/etc., then know that only the first 1024 message formats get cached and every single call to an Nth message format (N > 1024) results in new allocation.
// Consider using LoggerMessage.Define APIs instead
loggerFrom7MockProvidersMinLevelCritical.LogCritical(_messageTemplates[MaxCachedFormatters - 1], Name, Age, City, YearsSince, NumDonuts);
}
}
[Benchmark(OperationsPerInvoke = 5)]
public void LogCritical_CachedFormatter_NotUsed_LogEnabled_07_Providers()
{
if (loggerFrom7MockProvidersMinLevelCritical.IsEnabled(LogLevel.Critical))
{
// [B] If using LogWarning/LogInformation/etc., then know that only the first 1024 message formats get cached and every single call to an Nth message format (N > 1024) results in new allocation.
// Consider using LoggerMessage.Define APIs instead
loggerFrom7MockProvidersMinLevelCritical.LogCritical(_messageTemplates[MaxCachedFormatters], Name, Age, City, YearsSince, NumDonuts);
}
}
}
}
}

Benchmark analysis:

  • *Log_LogWarning_IsEnabledIfCheck_*: LogWarning (LogCritical, etc.) should be guarded with IsEnabled check to avoid bad perf and unnecessary allocations on LogX calls for which logger.IsEnabled(level) returns false
  • *_Generated*: For the generated code via LoggerMessageAttribute, would need to understand ways to improve its performance compared to non-generated log method. (one option is dotnet/runtime#51927). This way when SkipEnabledCheck is true, the generator would skip writing an IsEnabled call in favor of user-written IsEnabled calls around those methods
  • *_SkipEnabledCheck_True_*: There is a performance improvement with using skipEnabledCheck in general, but this perf gain gets negligible as number of arguments become higher or with more providers present.
  • *_Provider*: There is an overhead with adding more logging providers
  • *LogCritical_CachedFormatter_*: LogWarning (LogCritical, etc.) have an allocation hole on or after the 1024th message template to log for.
|----------------------------------------------------------------------------------------- |-------------:|------------:|------------:|----------:|-------:|------:|------:|----------:|
|                                                                                   Method |         Mean |       Error |      StdDev | Code Size |  Gen 0 | Gen 1 | Gen 2 | Allocated |
|----------------------------------------------------------------------------------------- |-------------:|------------:|------------:|----------:|-------:|------:|------:|----------:|
|                       Log_LogWarning_IsEnabledIfCheck_NotAdded_LogNotEnabled_0_Providers |   158.066 ns |   2.6798 ns |   3.3891 ns |     515 B | 0.0172 |     - |     - |     136 B |
|                          Log_LogWarning_IsEnabledIfCheck_Added_LogNotEnabled_0_Providers |     3.932 ns |   0.0970 ns |   0.1078 ns |     630 B |      - |     - |     - |         - |
|----------------------------------------------------------------------------------------- |-------------:|------------:|------------:|----------:|-------:|------:|------:|----------:|
|              Log_LoggerMessageDefine_SkipEnabledCheck_False_0args_LogEnabled_01_Provider |    44.110 ns |   0.9076 ns |   1.7046 ns |      31 B |      - |     - |     - |         - |
|               Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_01_Provider |    32.802 ns |   0.6777 ns |   1.2393 ns |      31 B |      - |     - |     - |         - |
|     Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_01_Provider_Generated |    44.008 ns |   0.9007 ns |   1.2917 ns |      86 B |      - |     - |     - |         - |
|              Log_LoggerMessageDefine_SkipEnabledCheck_False_2args_LogEnabled_01_Provider |   382.979 ns |   7.5085 ns |   7.3744 ns |      61 B | 0.0315 |     - |     - |     248 B |
|               Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_01_Provider |   365.748 ns |   6.8295 ns |  10.8323 ns |      61 B | 0.0315 |     - |     - |     248 B |
|     Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_01_Provider_Generated |   378.824 ns |   7.5654 ns |   8.0948 ns |     118 B | 0.0315 |     - |     - |     248 B |
|              Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_01_Provider |   581.339 ns |  11.5660 ns |  17.3115 ns |     108 B | 0.0458 |     - |     - |     360 B |
|               Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_01_Provider |   559.060 ns |  10.3151 ns |  16.3609 ns |     108 B | 0.0458 |     - |     - |     360 B |
|     Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_01_Provider_Generated |   573.217 ns |  11.3279 ns |  20.7137 ns |     198 B | 0.0458 |     - |     - |     360 B |
|              Log_LoggerMessageDefine_SkipEnabledCheck_False_0args_LogEnabled_10_Provider |   205.864 ns |   4.1033 ns |   4.7254 ns |      31 B |      - |     - |     - |         - |
|               Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_10_Provider |   193.097 ns |   3.8682 ns |   5.6700 ns |      31 B |      - |     - |     - |         - |
|     Log_LoggerMessageDefine_SkipEnabledCheck_True_0args_LogEnabled_10_Provider_Generated |   208.189 ns |   4.1800 ns |   6.3833 ns |      86 B |      - |     - |     - |         - |
|              Log_LoggerMessageDefine_SkipEnabledCheck_False_2args_LogEnabled_10_Provider | 3,383.198 ns |  67.0144 ns | 110.1065 ns |      61 B | 0.3128 |     - |     - |    2480 B |
|               Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_10_Provider | 3,400.620 ns |  67.9979 ns |  93.0763 ns |      61 B | 0.3128 |     - |     - |    2480 B |
|     Log_LoggerMessageDefine_SkipEnabledCheck_True_2args_LogEnabled_10_Provider_Generated | 3,440.425 ns |  56.8575 ns |  53.1846 ns |     118 B | 0.3128 |     - |     - |    2480 B |
|             Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_10_Providers | 5,360.688 ns | 104.9895 ns | 116.6955 ns |     108 B | 0.4578 |     - |     - |    3600 B |
|              Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_10_Providers | 5,345.059 ns | 103.8535 ns | 158.5953 ns |     108 B | 0.4578 |     - |     - |    3600 B |
|    Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_10_Providers_Generated | 5,280.591 ns | 105.4156 ns | 170.2265 ns |     198 B | 0.4578 |     - |     - |    3600 B |
|             Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_03_Providers | 1,608.661 ns |  31.0078 ns |  43.4686 ns |     108 B | 0.1373 |     - |     - |    1080 B |
|              Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_03_Providers | 1,558.619 ns |  30.9315 ns |  39.1184 ns |     108 B | 0.1373 |     - |     - |    1080 B |
|    Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_03_Providers_Generated | 1,604.554 ns |  31.1073 ns |  39.3407 ns |     198 B | 0.1373 |     - |     - |    1080 B |
|             Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_07_Providers | 3,627.123 ns |  68.2957 ns |  83.8732 ns |     108 B | 0.3204 |     - |     - |    2520 B |
|              Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_07_Providers | 3,602.748 ns |  71.5723 ns |  76.5816 ns |     108 B | 0.3204 |     - |     - |    2520 B |
|    Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_07_Providers_Generated | 3,620.133 ns |  60.2692 ns |  56.3758 ns |     198 B | 0.3204 |     - |     - |    2520 B |
|          Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogNotEnabled_07_Providers |    26.061 ns |   0.5557 ns |   0.7970 ns |     108 B |      - |     - |     - |         - |
|           Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogNotEnabled_07_Providers |    23.616 ns |   0.4921 ns |   0.7365 ns |     188 B |      - |     - |     - |         - |
| Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogNotEnabled_07_Providers_Generated |    24.411 ns |   0.5010 ns |   0.6336 ns |     200 B |      - |     - |     - |         - |
|             Log_LoggerMessageDefine_SkipEnabledCheck_False_5args_LogEnabled_00_Providers |     7.462 ns |   0.1786 ns |   0.2445 ns |     108 B |      - |     - |     - |         - |
|              Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_00_Providers |     4.326 ns |   0.1108 ns |   0.1185 ns |     188 B |      - |     - |     - |         - |
|    Log_LoggerMessageDefine_SkipEnabledCheck_True_5args_LogEnabled_00_Providers_Generated |     3.749 ns |   0.1065 ns |   0.1140 ns |     108 B |      - |     - |     - |         - |
|----------------------------------------------------------------------------------------- |-------------:|------------:|------------:|----------:|-------:|------:|------:|----------:|
|                                 LogCritical_CachedFormatter_Used_LogEnabled_07_Providers |   690.386 ns |  13.7883 ns |  13.5420 ns |     575 B | 0.0443 |     - |     - |     352 B |
|                              LogCritical_CachedFormatter_NotUsed_LogEnabled_07_Providers |   814.071 ns |  16.2581 ns |  25.3119 ns |     573 B | 0.0595 |     - |     - |     477 B |
|----------------------------------------------------------------------------------------- |-------------:|------------:|------------:|----------:|-------:|------:|------:|----------:|
@gfoidl
Copy link

gfoidl commented May 20, 2021

Nice analysis 👍

These "parameters" shouldn't be const, just plain fields to prevent any (C#) compiler optimizations, and reflect real-world usage better.
But I don't believe that won't change any of the points from the analysis.

I didn't run such exhaustive benchmarks, but from experience I can "confirm" these findings.

For improvements it boils down to using SkipEnabledCheck and trying to avoid boxing.

*_Provider*: There is an overhead with adding more logging providers

For IsEnabled this value could possible be cached? At least as long as the same "graph" of loggers is present.
Otherwise there's not much room for improvement I think.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment