search

serilog / serilog-extensions-logging

Serilog provider for Microsoft.Extensions.Logging
Apache License 2.0
313 stars 100 forks source link

Update to Serilog 4.x, remove some allocations #247

Open nblumhardt opened 6 months ago

nblumhardt commented 6 months ago

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