serilog-extensions-logging
serilog-extensions-logging copied to clipboard
Update to Serilog 4.x, remove some allocations
Updates to Serilog 4.x to elminate a dictionary construction using LogEvent.UnstableAssembleFromParts().
This gets the old LogInformation benchmark down from (a whopping) 1.26 KB/iteration to (a whopping) 1.17 KB/iteration.
But! The LogInformation benchmark is flawed, constructing a number of unrelated objects and doing some structure capturing, making it not representative of the overhead imposed by this library.
So, I've renamed it to Capturing, and its companion to CapturingScoped, and added some new benchmarks that should be closer to real-world average usage conditions.
Using Serilog.Extensions.Logging still halves throughput and more than doubles allocations compared with just using Serilog directly, but in real-world terms both setups will have pretty negligible effects on latency or GC load.
Before and After
BenchmarkDotNet v0.13.12, Ubuntu 22.04.4 LTS (Jammy Jellyfish)
13th Gen Intel Core i7-13700K, 1 CPU, 24 logical and 16 physical cores
.NET SDK 8.0.101
[Host] : .NET 8.0.2 (8.0.224.6711), X64 RyuJIT AVX2
DefaultJob : .NET 8.0.2 (8.0.224.6711), X64 RyuJIT AVX2
Before (main)
| Method | Mean | Error | StdDev | Gen0 | Allocated |
|---|---|---|---|---|---|
| LogInformation | 541.8 ns | 5.09 ns | 4.76 ns | 0.0820 | 1.26 KB |
| LogInformationScoped | 820.0 ns | 6.85 ns | 6.07 ns | 0.1431 | 2.2 KB |
| Method | Mean | Error | StdDev | Ratio | RatioSD | Gen0 | Allocated | Alloc Ratio |
|---|---|---|---|---|---|---|---|---|
| Native | 85.11 ns | 0.608 ns | 0.539 ns | 1.00 | 0.00 | 0.0188 | 296 B | 1.00 |
| NoId | 134.59 ns | 1.276 ns | 1.131 ns | 1.58 | 0.01 | 0.0274 | 432 B | 1.46 |
| LowNumbered | 199.86 ns | 0.948 ns | 0.887 ns | 2.35 | 0.02 | 0.0443 | 696 B | 2.35 |
| HighNumbered | 212.95 ns | 1.074 ns | 1.005 ns | 2.50 | 0.01 | 0.0494 | 776 B | 2.62 |
After
| Method | Mean | Error | StdDev | Gen0 | Allocated |
|---|---|---|---|---|---|
| LogInformation | 514.7 ns | 3.74 ns | 3.50 ns | 0.0763 | 1.17 KB |
| LogInformationScoped | 823.6 ns | 4.65 ns | 4.35 ns | 0.1431 | 2.2 KB |
| Method | Mean | Error | StdDev | Ratio | RatioSD | Gen0 | Allocated | Alloc Ratio |
|---|---|---|---|---|---|---|---|---|
| Native | 85.87 ns | 0.848 ns | 0.794 ns | 1.00 | 0.00 | 0.0188 | 296 B | 1.00 |
| NoId | 135.63 ns | 1.174 ns | 1.098 ns | 1.58 | 0.02 | 0.0279 | 440 B | 1.49 |
| LowNumbered | 173.26 ns | 1.031 ns | 0.964 ns | 2.02 | 0.02 | 0.0367 | 576 B | 1.95 |
| HighNumbered | 186.64 ns | 1.037 ns | 0.970 ns | 2.17 | 0.03 | 0.0417 | 656 B | 2.22 |
Updated benchmarks
The new benchmarks here compare various MEL + Serilog.Extensions.Logging scenarios to a plain _log.Information("Hello!") Serilog call.
| Method | Mean | Error | StdDev | Median | Ratio | RatioSD | Gen0 | Allocated | Alloc Ratio |
|---|---|---|---|---|---|---|---|---|---|
| SerilogOnly | 66.90 ns | 0.243 ns | 0.215 ns | 66.91 ns | 1.00 | 0.00 | 0.0101 | 160 B | 1.00 |
| SimpleEvent | 128.34 ns | 1.179 ns | 1.102 ns | 128.37 ns | 1.92 | 0.02 | 0.0279 | 440 B | 2.75 |
| Template | 183.58 ns | 2.037 ns | 1.906 ns | 182.80 ns | 2.75 | 0.03 | 0.0331 | 520 B | 3.25 |
| StringScope | 333.81 ns | 1.700 ns | 1.590 ns | 333.76 ns | 4.99 | 0.02 | 0.0696 | 1096 B | 6.85 |
| TemplateScope | 470.55 ns | 9.051 ns | 8.466 ns | 477.07 ns | 7.04 | 0.12 | 0.0839 | 1320 B | 8.25 |
| TupleScope | 383.44 ns | 1.441 ns | 1.277 ns | 383.32 ns | 5.73 | 0.03 | 0.0787 | 1240 B | 7.75 |
| DictionaryScope | 324.46 ns | 5.325 ns | 4.158 ns | 322.71 ns | 4.85 | 0.07 | 0.0739 | 1160 B | 7.25 |
| Capturing | 514.54 ns | 9.876 ns | 10.142 ns | 510.13 ns | 7.71 | 0.17 | 0.0763 | 1200 B | 7.50 |
| CapturingScope | 796.38 ns | 6.308 ns | 5.901 ns | 796.93 ns | 11.91 | 0.10 | 0.1431 | 2256 B | 14.10 |