serilog icon indicating copy to clipboard operation
serilog copied to clipboard

Avoid allocations for properties arrays for common cases

Open sungam3r opened this issue 3 years ago • 14 comments

These arrays are not stored further and are not used by user code.

sungam3r avatar Dec 04 '22 08:12 sungam3r

Need to fix Serilog.Tests.MethodOverloadConventionTests.ILoggerDefaultMethodsShouldBeInSyncWithLogger 😕 to skip new code.

sungam3r avatar Dec 04 '22 08:12 sungam3r

I must admit that this is an unusual test. I have never seen such tests before. Now it exist on

if (ifaceBytes.Length != classBytes.Length)
{
    return false;
}

since ifaceBytes is 39 bytes long and classBytes is 71 bytes long (for Void Write[T](Serilog.Events.LogEventLevel, System.String, T for example). Interfaces cannot contain instance fields. Even if I add static field in ILogger methods are still have different length. What should this test look like now?

sungam3r avatar Dec 04 '22 11:12 sungam3r

I think we'd need to be careful about the cost and concurrency impact of the memory barriers inserted by CompareExchange before taking this route

nblumhardt avatar Jan 24 '23 22:01 nblumhardt

dotnet test -c Release -f net7.0 --filter "FullyQualifiedName=Serilog.PerformanceTests.Harness.Pipeline"


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


before

Method Mean Error StdDev Gen0 Allocated
EmitLogEvent 155.6 ns 3.14 ns 4.99 ns 0.0448 376 B

after

Method Mean Error StdDev Gen0 Allocated
EmitLogEvent 152.2 ns 2.45 ns 2.17 ns 0.0410 344 B

sungam3r avatar Jan 25 '23 13:01 sungam3r

I only need help with Serilog.Tests.MethodOverloadConventionTests.ILoggerDefaultMethodsShouldBeInSyncWithLogger.

sungam3r avatar Jan 25 '23 13:01 sungam3r

@nblumhardt Would you like to see more tests?

sungam3r avatar Jan 30 '23 20:01 sungam3r

Looking good! I'll loop back to this ASAP - sorry about the delay

nblumhardt avatar Feb 03 '23 03:02 nblumhardt

Updated with changes from dev.

sungam3r avatar Feb 24 '23 07:02 sungam3r

failing on linux?

SimonCropp avatar Feb 25 '23 03:02 SimonCropp

I only need help with Serilog.Tests.MethodOverloadConventionTests.ILoggerDefaultMethodsShouldBeInSyncWithLogger.

Still need help.

sungam3r avatar Feb 25 '23 09:02 sungam3r

Rebased on dev. Still need help with Serilog.Tests.MethodOverloadConventionTests.ILoggerDefaultMethodsShouldBeInSyncWithLogger

sungam3r avatar May 21 '23 20:05 sungam3r

Rebased on dev. @nblumhardt Could you please help with Serilog.Tests.MethodOverloadConventionTests.ILoggerDefaultMethodsShouldBeInSyncWithLogger?

sungam3r avatar Jun 27 '23 14:06 sungam3r

The approach of using the single _reusableArrayOfX field for caching may cause contention between threads, as atomic writes do not scale well. And Interlocked.Exchange is write access.

The example of contention-free cache implementation can be found in dotnet/runtime PoolingAsyncValueTaskMethodBuilder<T> . This is a two-level cache, with per-thread and per-core slots.

For runtimes with Span<T> support, memory overhead can be reduced by allocating on the stack, instead of using an array on the heap.

epeshk avatar Aug 22 '23 14:08 epeshk

I think the synchronization-free stack allocation approach looks really promising; I'm inclined towards avoiding the atomics and heading in that direction - what do you think @sungam3r?

nblumhardt avatar Aug 23 '23 22:08 nblumhardt

Hi. I was away from actively supporting OSS for a long time. I like supposed solution, did not know about such API. @epeshk I have one question. I look at your code and it seems to me that boxing should occur on such lines for value types. изображение

I understand that the whole purpose of out PRs is to eliminate temporary array allocations for logged items of that array. Boxing of each item is out of scope of our intentions. So in both cases boxing takes place, right?

sungam3r avatar Mar 17 '24 15:03 sungam3r