Update to Serilog 4.x, remove some allocations

[nblumhardt]

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

[nblumhardt]

This should be [destructured.Name] = destructured.Value to avoid exceptions on duplicate keys.

[sungam3r]

bugfix?

[nblumhardt]

I don't think it'll have any effect in the way it's used, here, since events should never carry None - just makes the code clearer.

[sungam3r]

I would prefer to use ScalarValue.Null for property.Value is null check.

[nblumhardt]

👍 will take a look