Skip to content

Commit a446fa1

Browse files
stbychkovstbychkov
authored
Implemented generation of LoggerMessage.DefineScope to replace ILogger.BeginScope (#22)
Implemented generation of LoggerMessage.DefineScope functors to replace standard ILogger.BeginScope invocations
1 parent 4749e79 commit a446fa1

File tree

92 files changed

+2887
-578
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

92 files changed

+2887
-578
lines changed

‎README.md‎

Lines changed: 16 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -28,13 +28,23 @@ Check [this](https://github.com/stbychkov/AutoLoggerMessage/wiki/Configuration)
2828

2929
## Benchmarks
3030

31-
You can achieve performance boosts of up to 90% according to my benchmarks just by including this source generator in your project.
31+
You can achieve performance boosts of up to 90% just by including this source generator in your project.
3232

33-
| Configuration | Mean | Ratio | Allocated |
34-
|------------------------|-----------|-------|-----------|
35-
| Default implementation | 38.149 ns | 1.00 | 216 B |
36-
| Default + AutoLogger | 3.734 ns | 0.10 | - |
37-
| AutoLoggerMessage | 3.747 ns | 0.10 | - |
33+
For `ILogger.Log*` methods:
34+
35+
| Configuration | Mean | Ratio | Allocated |
36+
|-------------------------|-----------|-------|-----------|
37+
| Default implementation | 41.419 ns | 1.00 | 216 B |
38+
| Default + LoggerMessage | 4.004 ns | 0.10 | - |
39+
| AutoLoggerMessage | 4.577 ns | 0.11 | - |
40+
41+
And for `ILogger.DefineScope`:
42+
43+
| Configuration | Mean | Ratio | Allocated |
44+
|-------------------------|-----------|-------|-----------|
45+
| BeginScope | 39.566 ns | 1.00 | 216 B |
46+
| DefineScope | 5.197 ns | 0.13 | - |
47+
| AutoLoggerMessage | 5.296 ns | 0.13 | - |
3848

3949
Take a look at [benchmark](https://github.com/stbychkov/AutoLoggerMessage/wiki/Benchmarks) page for more details.
4050

‎benchmarks/AutoLoggerMessageGenerator.Benchmarks.csproj‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
</ItemGroup>
2222

2323
<ItemGroup>
24+
<ProjectReference Include="..\src\AutoLoggerMessageGenerator.BuildOutput\AutoLoggerMessageGenerator.BuildOutput.csproj" />
2425
<ProjectReference Include="..\src\AutoLoggerMessageGenerator\AutoLoggerMessageGenerator.Roslyn4_11.csproj"/>
2526
</ItemGroup>
2627

‎benchmarks/BenchmarkFiles/ExecutionTimeBenchmark.cs‎ renamed to ‎benchmarks/BenchmarkFiles/LogCallBenchmark.cs‎

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,15 +5,15 @@
55
[RankColumn]
66
[MemoryDiagnoser]
77
[GroupBenchmarksBy(BenchmarkLogicalGroupRule.ByCategory)]
8-
public partial class ExecutionTimeBenchmark
8+
public partial class LogCallBenchmark
99
{
1010
private ILogger _logger = null!;
1111
private ConfigurationExample _configuration = null!;
1212

1313
[GlobalSetup]
1414
public void Setup()
1515
{
16-
_logger = CustomNullLogger<ExecutionTimeBenchmark>.Instance;
16+
_logger = CustomNullLogger<LogCallBenchmark>.Instance;
1717
_configuration = new ConfigurationExample(
1818
0, "Root", new ConfigurationExample(
1919
1, "First Level", new ConfigurationExample(
@@ -29,6 +29,8 @@ public void LogInformationWithoutParameters()
2929
_logger.LogInformation("Hello world!");
3030
}
3131

32+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
33+
3234
[Benchmark]
3335
[BenchmarkCategory("Without parameters")]
3436
public void LoggerMessageWithoutParameters()
@@ -39,13 +41,17 @@ public void LoggerMessageWithoutParameters()
3941
[LoggerMessage(LogLevel.Information, Message = "Hello world!")]
4042
partial void LoggerMessageWithoutParametersImpl();
4143

44+
#endif
45+
4246
[Benchmark(Baseline = true)]
4347
[BenchmarkCategory("With 6 Parameters")]
4448
public void LogInformationWith6PrimitiveParameters()
4549
{
4650
_logger.LogInformation("Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}", 1, 2, 3, 4, 5, 6);
4751
}
4852

53+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
54+
4955
[Benchmark]
5056
[BenchmarkCategory("With 6 Parameters")]
5157
public void LoggerMessageWith6Parameters()
@@ -56,13 +62,17 @@ public void LoggerMessageWith6Parameters()
5662
[LoggerMessage(LogLevel.Information, Message = "Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}")]
5763
partial void LoggerMessageWith6ParametersImpl(int arg1, int arg2, int arg3, int arg4, int arg5, int arg6);
5864

65+
#endif
66+
5967
[Benchmark(Baseline = true)]
6068
[BenchmarkCategory("With 7 Parameters")]
6169
public void LogInformationWith7PrimitiveParameters()
6270
{
6371
_logger.LogInformation("Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6} {arg7}", 1, 2, 3, 4, 5, 6, 7);
6472
}
6573

74+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
75+
6676
[Benchmark]
6777
[BenchmarkCategory("With 7 Parameters")]
6878
public void LoggerMessageWith7Parameters()
@@ -74,6 +84,8 @@ public void LoggerMessageWith7Parameters()
7484
partial void LoggerMessageWith7ParametersImpl(int arg1, int arg2, int arg3, int arg4, int arg5, int arg6,
7585
int arg7);
7686

87+
#endif
88+
7789
[Benchmark(Baseline = true)]
7890
[BenchmarkCategory("With Complex Types Parameters")]
7991
public void LogInformationWithComplexParameters()
@@ -82,6 +94,7 @@ public void LogInformationWithComplexParameters()
8294
_configuration, _configuration, _configuration, _configuration, _configuration, _configuration);
8395
}
8496

97+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
8598
[Benchmark]
8699
[BenchmarkCategory("With Complex Types Parameters")]
87100
public void LoggerMessageWithComplexParameters()
@@ -102,6 +115,8 @@ partial void LoggerMessageWithComplexParametersImpl(
102115
ConfigurationExample arg6
103116
);
104117

118+
#endif
119+
105120
#if TELEMETRY
106121

107122
[Benchmark]

‎benchmarks/BenchmarkFiles/LogScopeBenchmark.cs‎

Lines changed: 109 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,109 @@
1+
using BenchmarkDotNet.Attributes;
2+
using BenchmarkDotNet.Configs;
3+
using Microsoft.Extensions.Logging;
4+
5+
[RankColumn]
6+
[MemoryDiagnoser]
7+
[GroupBenchmarksBy(BenchmarkLogicalGroupRule.ByCategory)]
8+
public partial class LogScopeBenchmark
9+
{
10+
private ILogger _logger = null!;
11+
private ConfigurationExample _configuration = null!;
12+
13+
[GlobalSetup]
14+
public void Setup()
15+
{
16+
_logger = CustomNullLogger<LogScopeBenchmark>.Instance;
17+
_configuration = new ConfigurationExample(
18+
0, "Root", new ConfigurationExample(
19+
1, "First Level", new ConfigurationExample(
20+
2, "Second level", null)
21+
)
22+
);
23+
}
24+
25+
#if !TELEMETRY
26+
27+
[Benchmark(Baseline = true)]
28+
[BenchmarkCategory("Without parameters")]
29+
public void BeginScopeWithoutParameters()
30+
{
31+
using var _ = _logger.BeginScope("Hello world!");
32+
}
33+
34+
#endif
35+
36+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
37+
38+
[Benchmark]
39+
[BenchmarkCategory("Without parameters")]
40+
public void LoggerDefineScopeWithoutParameters()
41+
{
42+
using var _ = _loggerDefineScopeWithoutParameters(_logger);
43+
}
44+
45+
private static readonly Func<ILogger, IDisposable?> _loggerDefineScopeWithoutParameters =
46+
LoggerMessage.DefineScope("Hello world!");
47+
48+
#endif
49+
50+
#if !TELEMETRY
51+
[Benchmark(Baseline = true)]
52+
[BenchmarkCategory("With 6 Parameters")]
53+
public void BeginScopeWith6PrimitiveParameters()
54+
{
55+
using var _ = _logger.BeginScope("Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}", 1, 2, 3, 4, 5, 6);
56+
}
57+
#endif
58+
59+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
60+
61+
[Benchmark]
62+
[BenchmarkCategory("With 6 Parameters")]
63+
public void LoggerDefineScopeWith6Parameters()
64+
{
65+
using var _ = _loggerDefineScopeWith6Parameters(_logger, 1, 2, 3, 4, 5, 6);
66+
}
67+
68+
private static readonly Func<ILogger, int, int, int, int, int, int, IDisposable?> _loggerDefineScopeWith6Parameters =
69+
LoggerMessage.DefineScope<int, int, int, int, int, int>("Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}");
70+
71+
#endif
72+
73+
#if !TELEMETRY
74+
75+
[Benchmark(Baseline = true)]
76+
[BenchmarkCategory("With Complex Types Parameters")]
77+
public void BeginScopeWithComplexParameters()
78+
{
79+
using var _ = _logger.BeginScope("Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}",
80+
_configuration, _configuration, _configuration, _configuration, _configuration, _configuration);
81+
}
82+
83+
#endif
84+
85+
#if DEFAULT && !TELEMETRY && !AUTO_LOGGER_MESSAGE
86+
87+
[Benchmark]
88+
[BenchmarkCategory("With Complex Types Parameters")]
89+
public void LoggerDefineScopeWithComplexParameters()
90+
{
91+
using var _ = _loggerDefineScopeWithComplexParameters(_logger,
92+
_configuration, _configuration, _configuration,
93+
_configuration, _configuration, _configuration
94+
);
95+
}
96+
97+
private static readonly Func<ILogger, ConfigurationExample, ConfigurationExample,
98+
ConfigurationExample, ConfigurationExample, ConfigurationExample,
99+
ConfigurationExample, IDisposable?> _loggerDefineScopeWithComplexParameters =
100+
LoggerMessage.DefineScope<ConfigurationExample, ConfigurationExample,
101+
ConfigurationExample, ConfigurationExample,
102+
ConfigurationExample, ConfigurationExample>(
103+
"Hello world! {arg1} {arg2} {arg3} {arg4} {arg5} {arg6}"
104+
);
105+
106+
#endif
107+
108+
public record ConfigurationExample(int Id, string Name, ConfigurationExample? NestedConfiguration);
109+
}

‎benchmarks/PackagesProvider.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,5 +5,6 @@ internal static class PackagesProvider
55
public const string BenchmarkPackage = """<PackageReference Include="BenchmarkDotNet"/>""";
66
public const string MicrosoftExtensionsLoggingPackage = """<PackageReference Include="Microsoft.Extensions.Logging.Abstractions"/>""";
77
public const string MicrosoftExtensionsTelemetryPackage = """<PackageReference Include="Microsoft.Extensions.Telemetry.Abstractions"/>""";
8-
public const string AutoLoggerMessagePackage = """<ProjectReference Include="..\..\..\..\..\..\AutoLoggerMessageGenerator\AutoLoggerMessageGenerator.csproj" ReferenceOutputAssembly="true" OutputItemType="Analyzer" />""";
8+
public const string AutoLoggerMessageBuildOutput = """<Reference Include="AutoLoggerMessageGenerator.BuildOutput" HintPath="..\AutoLoggerMessageGenerator.BuildOutput.dll"/>""";
9+
public const string AutoLoggerMessagePackage = """<Analyzer Include="..\AutoLoggerMessageGenerator.dll"/>""";
910
}

‎benchmarks/Program.cs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
{
2929
PackagesProvider.BenchmarkPackage,
3030
PackagesProvider.MicrosoftExtensionsLoggingPackage,
31+
PackagesProvider.AutoLoggerMessageBuildOutput,
3132
PackagesProvider.AutoLoggerMessagePackage
3233
}
3334
},
@@ -38,6 +39,7 @@
3839
{
3940
PackagesProvider.BenchmarkPackage,
4041
PackagesProvider.AutoLoggerMessagePackage,
42+
PackagesProvider.AutoLoggerMessageBuildOutput,
4143
PackagesProvider.MicrosoftExtensionsLoggingPackage,
4244
PackagesProvider.MicrosoftExtensionsTelemetryPackage,
4345
}

‎benchmarks/ProjectBuilder.cs‎

Lines changed: 14 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -55,9 +55,7 @@ private static void CopyBenchmarkFiles(string workingDirectory)
5555

5656
private async Task<(string OutputFolder, string projFilePath)> GenerateProjectFile(string projectName, string workingDirectory)
5757
{
58-
var telemetryConstant = projectConfiguration.References.Contains(PackagesProvider.MicrosoftExtensionsTelemetryPackage)
59-
? "TELEMETRY"
60-
: string.Empty;
58+
var configurations = string.Join(";", GetProjectConfigurations());
6159

6260
var targetFramework = TargetFrameworkMonikerDetector.Detect();
6361

@@ -74,7 +72,7 @@ private static void CopyBenchmarkFiles(string workingDirectory)
7472
<AppendRuntimeIdentifierToOutputPath>false</AppendRuntimeIdentifierToOutputPath>
7573
<IntermediateOutputPath>{outputFolder}</IntermediateOutputPath>
7674
<RootNamespace>{projectName}</RootNamespace>
77-
<DefineConstants>$(DefineConstants);{telemetryConstant}</DefineConstants>
75+
<DefineConstants>$(DefineConstants);{configurations}</DefineConstants>
7876
</PropertyGroup>
7977
8078
<PropertyGroup>
@@ -99,6 +97,18 @@ private static void CopyBenchmarkFiles(string workingDirectory)
9997
return (outputFolder, projFilePath);
10098
}
10199

100+
private IEnumerable<string> GetProjectConfigurations()
101+
{
102+
if (projectConfiguration.References.Contains(PackagesProvider.MicrosoftExtensionsLoggingPackage))
103+
yield return "DEFAULT";
104+
105+
if (projectConfiguration.References.Contains(PackagesProvider.MicrosoftExtensionsTelemetryPackage))
106+
yield return "TELEMETRY";
107+
108+
if (projectConfiguration.References.Contains(PackagesProvider.AutoLoggerMessagePackage))
109+
yield return "AUTO_LOGGER_MESSAGE";
110+
}
111+
102112
internal class BuildResult
103113
{
104114
public required string ProjectDirectory { get; init; }

‎docs/ADR/ADR-07_Generation_of_BeginScope_methods.md‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
### Title: ADR-07 Generation of `BeginScope` methods
2+
### Status: Accepted
3+
4+
### Context:
5+
6+
The existing `ILogger.BeginScope` method has the same problems as the `ILogger.Log*` methods:
7+
1. Lack of compile-time checks for mismatches between template parameters and the actual arguments, which can lead to runtime exceptions.
8+
2. Performance overhead due to the need to create a new scope object every time.
9+
3. Unnecessary allocations due to boxing of template parameters, even with identical arguments.
10+
11+
`ILogger.BeginScope` is backed by `LoggerMessage.DefineScope`, which allows generation of strongly-typed, precompiled delegates with up to 6 parameters. This enables high-performance and allocation-free scope creation, similar to how `LoggerMessage.Define` is used for logging methods.
12+
13+
The main difference is that `ILogger.BeginScope` **with only one parameter** is an instance method, not an extension method. This means we cannot intercept or replace calls that only use a single message argument (i.e., `BeginScope("Starting operation")`) because the instance method takes precedence over extension methods. Therefore, generation will be limited to `BeginScope` calls with one or more structured parameters (i.e., key-value pairs or anonymous objects), which typically benefit the most from strongly-typed scope generation.
14+
[Reference test](https://github.com/stbychkov/AutoLoggerMessage/blob/main/tests/AutoLoggerMessageGenerator.UnitTests/MethodSpecificityRules/InstanceCallVsExtensionCallTests.cs)
15+
16+
### Decision:
17+
18+
Extend the AutoLoggerMessage source generator to support generation of strongly-typed scope delegates using `LoggerMessage.DefineScope`.
19+
20+
Specifically:
21+
- Identify all usages of `ILogger.BeginScope` in the codebase where the call includes **at least one structured argument** (excluding pure string messages).
22+
- For each identified scope usage:
23+
- Generate a static readonly field that contains the compiled scope delegate using `LoggerMessage.DefineScope`.
24+
- Generate an extension method (or internal interceptor method) that redirects the original `BeginScope` call to the generated delegate, preserving structure and performance.
25+
- Ensure that the generated methods follow the same naming, visibility, and partial class strategy as existing `Log*` method interceptors.
26+
27+
### Consequences:
28+
29+
* **Short-term**:
30+
- Improves performance and reduces allocations for scoped logging with parameters.
31+
- Introduces new source generation complexity; testing must be extended to validate generated scopes.
32+
33+
* **Long-term**:
34+
- Moves the library closer to complete compile-time safety for all common logging patterns (`Log*` and `BeginScope`).
35+
36+
* **Risks**:
37+
- May cause confusion if developers attempt to use `BeginScope(string message)` expecting interception (which is not supported).
38+
- Reliance on exact call shapes (number and types of arguments) may introduce fragility unless thoroughly tested.
39+
40+
* **Maintenance**:
41+
- Must track and test against future changes in `LoggerMessage.DefineScope` API (currently supports up to 6 parameters).
42+
- Increases the surface area of generated code, potentially impacting future refactors or compatibility with downstream tools.
43+
44+
### Alternatives Considered
45+
46+
* **Do nothing**: Keep relying on `ILogger.BeginScope` as is. This maintains simplicity but misses out on performance and compile-time safety.

0 commit comments

Comments
 (0)