Struct alternative to LogEventProperty; optimizations

[nblumhardt]

This replaces some internal usage of the class LogEventProperty with a new, very similar, struct EventProperty.

The changes reduce allocations in message template binding/event construction, and in ForContext(name, value), by a very modest amount.

Along the way, a couple of small opportunistic changes - some IEnumerable<T> over arrays was replaced with direct array passing, and copying of events (i.e. for WriteTo.Logger()) was refactored to allow the new event's properties dictionary to be constructed with the correct capacity.

BenchmarkDotNet=v0.11.5, OS=Windows 10.0.17763.503 (1809/October2018Update/Redstone5)
Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
.NET Core SDK=2.2.204
  [Host] : .NET Core 2.2.5 (CoreCLR 4.6.27617.05, CoreFX 4.6.27618.01), 64bit RyuJIT
  Clr    : .NET Framework 4.7.2 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.3416.0
  Core   : .NET Core 2.2.5 (CoreCLR 4.6.27617.05, CoreFX 4.6.27618.01), 64bit RyuJIT

Pipeline benchmark (.NET Core 2.2)

This shows 56 fewer bytes allocated (12%) when binding/constructing a log event with one property. The gain here will be in proportion to the number of properties bound from the message template.

The difference is consistent across .NET Core and Framework.

Before:

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
EmitLogEvent	431.6 ns	6.900 ns	6.454 ns	0.1369	-	-	432 B

After:

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
EmitLogEvent	416.2 ns	4.975 ns	4.653 ns	0.1192	-	-	376 B

Remaining work

Some more benchmarking is needed. I ran the allocations benchmark suite but apart from in the simple logging case that matches the pipeline benchmark above, differences were mostly noise, buried by the other work being done.

There also remains a regression in Logger.BindMessageTemplate() due to the need to present LogEventPropertys on the API surface.

[nblumhardt]

Nested logger creation (.NET Core 2.2)

Removed an allocation (15% fewer bytes on the most common two cases); added a small string hot path optimization in PropertyValueConverter, reorder to avoid TLS and a GetType() call during property value conversion. Nice little speed-up.

Before:

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
ForContextString	109.5 ns	1.3622 ns	1.2742 ns	0.0483	-	-	152 B
ForContextType	144.7 ns	1.1916 ns	1.1146 ns	0.0482	-	-	152 B
ForContextInt	100.0 ns	0.7645 ns	0.7151 ns	0.0559	-	-	176 B

After:

Method	Mean	Error	StdDev	Gen 0	Gen 1	Gen 2	Allocated
ForContextString	64.56 ns	0.9045 ns	0.8461 ns	0.0407	-	-	128 B
ForContextType	111.04 ns	1.2752 ns	1.0648 ns	0.0407	-	-	128 B
ForContextInt	103.95 ns	0.9308 ns	0.8251 ns	0.0482	-	-	152 B

[nblumhardt]

Binding benchmark (.NET Core 2.2)

The PR introduces a regression in Logger.BindMessageTemplate(); the method is not used internally, and doesn't appear to be used widely in the ecosystem (I checked Serilog.Extensions.Logging - one of the possible consumers mentioned in #746, but it's using BindProperty() instead).

To quantify:

Before:

Method	Mean	Error	StdDev	Ratio	RatioSD	Gen 0	Gen 1	Gen 2	Allocated
BindZero	59.31 ns	0.6348 ns	0.5627 ns	1.00	0.00	-	-	-	-
BindOne	149.77 ns	2.4367 ns	2.0347 ns	2.53	0.05	0.0279	-	-	88 B
BindFive	461.22 ns	4.4476 ns	4.1603 ns	7.78	0.09	0.1092	-	-	344 B

After:

Method	Mean	Error	StdDev	Ratio	RatioSD	Gen 0	Gen 1	Gen 2	Allocated
BindZero	65.32 ns	0.7988 ns	0.7081 ns	1.00	0.00	-	-	-	-
BindOne	223.89 ns	0.9839 ns	0.9203 ns	3.43	0.04	0.0455	-	-	144 B
BindFive	594.10 ns	5.8526 ns	5.4746 ns	9.10	0.13	0.1364	-	-	432 B

[nblumhardt]

I think this is ready to go, but I can't figure out why the UWP tests are failing on the newer SDK (not running a version of VS that suppports UWP projects :-))

Anyone have any ideas? 😊

[nblumhardt]

😓 ... going .. to ... get .. this ... building ... on new SDK!

[nblumhardt]

👏 building! Anyone keen to sanity check this? :-)

[nblumhardt]

(Will need a squash/merge.)

The churn here is due to wanting to use newer C# features - readonly and in structs in this case. Good opportunity to bring the toolchain forward, anyway. No breaking changes 🤞

[nblumhardt]

If all's quiet I'll shoot this through to dev, folks (I think it's a safe win...) 😁

[merbla]

LGTM

[nblumhardt]

Thanks for the quick scan, @merbla and @adamchester ... Hitting that button now! :-)

[adamchester]

LGTM