Demonstration of pooling of LogEvent instances

[sungam3r]

As a continuation of discussions from #1772. See benchmarks here https://github.com/serilog/serilog/pull/1788#issuecomment-1405345035

[sungam3r]

@nblumhardt this is demo only, see API changes diff. No backward breaking changes, only new APIs. No new dependencies. In some cases -- one-threaded/console apps -- these approach can archive 100% reuse of created LogEvent instances.

[igor84]

I see now. Very nice solution. You even implemented a way for users to provide custom pooling solutions. You are counting that users only opt into log event pooling if they know they are using sinks and enrichers that will not keep the logEvent reference around so the only downside would be that nothing actually stops users from making such mistake and getting weird results.

[sungam3r]

Yes, you got the idea.

[sungam3r]

You even implemented a way for users to provide custom pooling solutions.

It turned out by itself, because I had no other choice.

[vlm---]

Can it somehow identify sinks / enrichers without support for pooling while its running and write error to selflog / throw? Reading source code / debugging through for every used sink would be tedious at best.

[sungam3r]

I think that it is impossible. One can just store the reference to LogEvent and use it as he see fit.

[sungam3r]

I would say that all syncronous sinks support pooling and async sinks may support pooling.

[cocowalla]

Keen to see if you have you ran any benchmarks yet?

EDIT: nevermind, I see them here now 😄

[sungam3r]

#1780 is about different memory optimization. Give me some time to add results here - today or tomorrow.

[sungam3r]

Slightly modified PipelineBenchmark benchmark:

// Copyright 2013-2016 Serilog Contributors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

using PoolRunner;

namespace Serilog.PerformanceTests;

/// <summary>
/// Tests the cost of writing through the logging pipeline.
/// </summary>
[MemoryDiagnoser]
public class PipelineBenchmark
{
    ILogger _log1 = null!;
    ILogger _log2 = null!;
    Exception _exception = null!;

    [GlobalSetup]
    public void Setup()
    {
        _exception = new Exception("An Error");
        _log1 = new LoggerConfiguration()
            .WriteTo.Sink(new NullSink())
            .CreateLogger();

        // Ensure template is cached
        _log1.Information(_exception, "Hello, {Name}!", "World");

        _log2 = new LoggerConfiguration()
           .WriteTo.Sink(new NullSink())
           .CreateLogger().Pooled();

        // Ensure template is cached
        _log2.Information(_exception, "Hello, {Name}!", "World");
    }

    [Benchmark(Baseline = true)]
    public void EmitLogEvent()
    {
        _log1.Information(_exception, "Hello, {Name}!", "World");
    }

    [Benchmark]
    public void EmitLogEventPooled()
    {
        _log2.Information(_exception, "Hello, {Name}!", "World");
    }
}

Results:

BenchmarkDotNet=v0.13.2, OS=Windows 11 (10.0.22621.1105)
AMD Ryzen 7 6800H with Radeon Graphics, 1 CPU, 16 logical and 8 physical cores
.NET SDK=7.0.102
  [Host]     : .NET 7.0.2 (7.0.222.60605), X64 RyuJIT AVX2
  DefaultJob : .NET 7.0.2 (7.0.222.60605), X64 RyuJIT AVX2

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen0	Allocated	Alloc Ratio
EmitLogEvent	161.9 ns	3.24 ns	7.19 ns	159.1 ns	1.00	0.00	0.0448	376 B	1.00
EmitLogEventPooled	140.0 ns	2.56 ns	2.40 ns	138.8 ns	0.84	0.04	0.0114	96 B	0.26

😮

[sungam3r]

EventLog really consumes a lot of memory.

[sungam3r]

Of course with Dictionary<string, LogEventPropertyValue> inside. I intentionally reused private dictionary.

[sungam3r]

Disclaimer: results may vary due to maximumRetained argument which is 1 by default.

[sungam3r]

@nblumhardt What do you think? Memory consumption decreased by 4 times and it seems that pooled path works event a bit faster. Of course experience may vary.

[sungam3r]

@nblumhardt Will it be included in v3 release? No breaking changes.

[nblumhardt]

I think this one's a cool demo but probably not something I'd want to jump into at this point. Happy to keep it on the backburner and discuss post-3.0, though. I think it'd need a lot of thought around how the feature might be misused/potential bugs/drawbacks/footguns.

[Saibamen]

Related: https://github.com/serilog/serilog/issues/1769