|
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); |
|
} |
|
} |
|
} |
|
} |
|
} |
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.
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.