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 (aspnet/Announcements#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:

   runtime/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerExtensions.cs

   Line 393 in 3c1b48e

   logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);

2. For KeyValuePair<string, string> gets instantiated in the GetProperties call below:

   runtime/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs

   Lines 196 to 210 in 5ae76c5

   	private IReadOnlyList<KeyValuePair<string, string>> GetProperties(object state)
   	{
   	if (state is IReadOnlyList<KeyValuePair<string, object>> keyValuePairs)
   	{
   	var arguments = new KeyValuePair<string, string>[keyValuePairs.Count];
   	for (int i = 0; i < keyValuePairs.Count; i++)
   	{
   	KeyValuePair<string, object> keyValuePair = keyValuePairs[i];
   	arguments[i] = new KeyValuePair<string, string>(keyValuePair.Key, keyValuePair.Value?.ToString());
   	}
   	return arguments;
   	}
   	return Array.Empty<KeyValuePair<string, string>>();
   	}

• 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

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

Line 1303 in 171ef84

protected unsafe void WriteEvent(int eventId, params object?[] args)

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

runtime/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs

Lines 159 to 165 in 171ef84

	internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string>> Arguments)
	{
	if (IsEnabled())
	{
	WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments);
	}
	}

runtime/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs

Lines 171 to 177 in 171ef84

	internal void ActivityStart(int ID, int FactoryID, string LoggerName, IEnumerable<KeyValuePair<string, string>> Arguments)
	{
	if (IsEnabled())
	{
	WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
	}
	}

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.