azure-sdk-for-net icon indicating copy to clipboard operation
azure-sdk-for-net copied to clipboard

Reduce memory allocation in EventSourceEventFormatting

Open pharring opened this issue 9 months ago • 4 comments

This is a performance improvement for EventSourceEventFormatting to reduce the memory allocated in common cases.

There are two optimization techniques:

  1. Use a cached StringBuilder
  2. Use Convert.ToHexString, where available (.NET 6 and above). Where not available, if the string is small enough, use Span with stackalloc

Benchmarks are already present for EventSourceListener:

Baseline

Method Runtime Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
'Old implementation' .NET 6.0 6.762 us 0.6321 us 0.7280 us 1.00 0.00 - 6.38 KB 1.00
'New implementation, includes reformatting' .NET 6.0 7.323 us 0.6139 us 0.7070 us 1.10 0.18 - 6.83 KB 1.07
'New implementation, no reformatting' .NET 6.0 5.096 us 0.5186 us 0.5972 us 0.76 0.07 - 5.07 KB 0.80
'Old implementation' .NET Framework 4.6.2 13.782 us 1.6758 us 1.9298 us 1.00 0.00 2.7938 17.39 KB 1.00
'New implementation, includes reformatting' .NET Framework 4.6.2 23.269 us 2.4829 us 2.8593 us 1.70 0.17 2.9446 18.36 KB 1.06
'New implementation, no reformatting' .NET Framework 4.6.2 18.491 us 2.1708 us 2.4999 us 1.34 0.06 2.5934 16.13 KB 0.93

Candidate

Method Runtime Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
'Old implementation' .NET 6.0 2.902 us 0.0858 us 0.0988 us 1.00 0.00 - 3 KB 1.00
'New implementation, includes reformatting' .NET 6.0 3.453 us 0.0427 us 0.0400 us 1.19 0.05 - 3.45 KB 1.15
'New implementation, no reformatting' .NET 6.0 1.292 us 0.0299 us 0.0344 us 0.45 0.02 - 1.7 KB 0.57
'Old implementation' .NET Framework 4.6.2 4.646 us 0.3443 us 0.3965 us 1.00 0.00 0.5874 3.67 KB 1.00
'New implementation, includes reformatting' .NET Framework 4.6.2 12.413 us 0.7478 us 0.8612 us 2.69 0.31 0.7331 4.63 KB 1.26
'New implementation, no reformatting' .NET Framework 4.6.2 8.836 us 0.5962 us 0.6865 us 1.92 0.26 0.3878 2.4 KB 0.65

Memory reductions across the board and also at least 2x speed ups.

pharring avatar May 09 '24 03:05 pharring

Thank you for your contribution @pharring! We will review the pull request and get back to you soon.

github-actions[bot] avatar May 09 '24 03:05 github-actions[bot]

API change check

API changes are not detected in this pull request.

azure-sdk avatar May 09 '24 03:05 azure-sdk

//cc: @KrzysztofCwalina, @christothes, @JoshLove-msft, @annelo-msft - I'd appreciate a second pair of eyes on this before merging.

jsquire avatar May 10 '24 21:05 jsquire

Before anyone else points it out, this bottleneck arises because we do eager string formatting of every event written to the AzureEventSourceListener (if a logger is passed in the constructor). AzureEventSourceListener is used by Azure.Monitor.OpenTelemetry's AzureEventSourceLogForwarder and it doesn't even use the string: https://github.com/Azure/azure-sdk-for-net/blob/c4418cd3e85f2e01a92b702414244647ff3695df/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/Internals/AzureSdkCompat/AzureEventSourceLogForwarder.cs#L70

Would it be OK to add an overloaded constructor on AzureEventSourceListener that takes an Action<EventWrittenEventArgs>? Then we can avoid calling EventSourceEventFormatting entirely.

pharring avatar May 10 '24 22:05 pharring

Would it be OK to add an overloaded constructor on AzureEventSourceListener that takes an Action<EventWrittenEventArgs>? Then we can avoid calling EventSourceEventFormatting entirely.

AzureEventSourceLogForwarder does actually seem to call Format, though in a strange way:

https://github.com/Azure/azure-sdk-for-net/blob/c4418cd3e85f2e01a92b702414244647ff3695df/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/Internals/AzureSdkCompat/AzureEventSourceLogForwarder.cs#L64

which calls EventSourceEventFormatting.Format: https://github.com/Azure/azure-sdk-for-net/blob/2a0e020ae9348cb31af769027efd6b1491595a9d/sdk/core/Azure.Core/src/Shared/EventSourceEvent.cs#L58

So it seems to be formatting twice

christothes avatar May 14 '24 22:05 christothes

@christothes can this be merged now? I don't have permission myself.

pharring avatar Jul 16 '24 19:07 pharring