Improve perfomance for EventSourceLoggerProvider with EventPipe active

[davidfowl]

We've already spent some cycles improving the noop case here now we need to look more closely at the overhead when using dotnet trace:

When running an ASP.NET Core application with just the event source logger and this command line to collect logs:

dotnet trace collect -p 42748 --providers Microsoft-Extensions-Logging:2:1

Here's what the allocations look like:

Some of these are inside of EventSource itself and some are inside of the Logger provider implementation.

@shirhatti

[ghost]

As part of the migration of components from dotnet/extensions to dotnet/runtime (https://github.com/aspnet/Announcements/issues/411) we will be bulk closing some of the older issues. If you are still interested in having this issue addressed, just comment and the issue will be automatically reactivated (even if you aren't the author). When you do that, I'll page the team to come take a look. If you've moved on or workaround the issue and no longer need this change, just ignore this and the issue will be closed in 7 days.

If you know that the issue affects a package that has moved to a different repo, please consider re-opening the issue in that repo. If you're unsure, that's OK, someone from the team can help!

[shirhatti]

@ericstj How do use labels/milestones on your team? I want to make sure we bring this up during triage as a 5.0 candidate

[ericstj]

@davidfowl is the goal here to make this completely allocation free at steady state? Did you have specific ideas for low-hanging fruit that we should look at first?

[davidfowl]

@ericstj as close as we can get to that. I can't remember where those allocations were coming from. We should get a new profile to see if any of the low hanging fruit sticks out.

[maryamariyan]

Here's a short summary of an experimentation:

using

            for (int i = 0; i < 10000; i++)
            {
                _logger.LogCritical("logging critical info");
            }

The below screenshot shows the allocations meanwhile dotnet trace is running for above application process:

From going over the callstacks:

1) FormattedLogValues gets instantiated below: https://github.com/dotnet/runtime/blob/3c1b48ee29f13cac93a86829374b917375a49a2d/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerExtensions.cs#L393

2) For KeyValuePair<string, string> gets instantiated in the GetProperties call below: https://github.com/dotnet/runtime/blob/5ae76c503b78d99c96eb8970a98c408af842a562/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs#L196-L210

• [ ] TODO: Confirm in the screenshot KeyValuePair<string, string> is an array. (consider perhaps using ArrayPool here.)

3) Then as part of the Log API implemented by EventSourceLogger we end up boxing data such as KeyValuePair<string, string>, LogLevel, int, etc. when

https://github.com/dotnet/runtime/blob/171ef84617fe54c2a94019f729e61b077554047c/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L1303

ultimately gets called. This happens when calling the internal LoggingEventSource APIs such as Message(..), ActivityStart(..) as shown below:

https://github.com/dotnet/runtime/blob/171ef84617fe54c2a94019f729e61b077554047c/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs#L159-L165

https://github.com/dotnet/runtime/blob/171ef84617fe54c2a94019f729e61b077554047c/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs#L171-L177

Causing the extra memory allocations seen in the screenshot. Workaround could be to add overloads instead of having the one with params get called

cc: @noahfalk

I have a Diagnostics Hub Report file (*.diagsession) but github doesnt allow attaching to a comment here.