Fix the boxing when using the LoggerMessage.Define is used and values are converted ToString

[davidfowl]

Description

Today LoggerMessage.Define is a high performance logging API that aims to reduce the overhead of logging by pre-parsing format strings and parameters holes to log. Today the values are stored in a LogValues<T0,...,TN> struct to avoid boxing. We do all of this work only to eventually box these arguments and allocate an array to turn this into a string. We should avoid the object[] and the boxing here.

Regression?

No

Data

using System;
using Microsoft.Extensions.Logging;

namespace ConsoleApp105
{
    class Program
    {
        static void Main(string[] args)
        {
            var callback = LoggerMessage.Define<int, int>(LogLevel.Information, new(0, "Event"), "This is a {Value} and a {Score}");
            var logger = new Logger();

            Console.WriteLine("Waiting");
            Console.ReadLine();

            for (int i = 0; i < 10000; i++)
            {
                callback(logger, 1, 0, null);
            }

            Console.WriteLine("Done");
            Console.ReadLine();

        }

        public class Logger : ILogger
        {
            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }

            public bool IsEnabled(LogLevel logLevel)
            {
                return true;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            {
                var value = formatter(state, exception);
                LogToSomeplace(value);
            }

            private void LogToSomeplace(string value)
            {
                
            }
        }
    }
}

Type	Allocations	Bytes	Average Size (Bytes)
- System.Int32	20,010	480,240	24
- System.String	12,115	957,270	79.02

When I add a 4 int parameters:

Type	Allocations	Bytes	Average Size (Bytes)
- System.String	12,119	1,217,518	100.46
- System.Int32	40,010	960,240	24
- System.Object[4]	10,000	560,000	56

Analysis

We need to implement non-allocating formatting for these calls

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

Lines 158 to 189 in 89498d8

	internal string FormatWithOverwrite(object?[]? values)
	{
	if (values != null)
	{
	for (int i = 0; i < values.Length; i++)
	{
	values[i] = FormatArgument(values[i]);
	}
	}
	return string.Format(CultureInfo.InvariantCulture, _format, values ?? Array.Empty<object>());
	}
	internal string Format()
	{
	return _format;
	}
	internal string Format(object? arg0)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0));
	}
	internal string Format(object? arg0, object? arg1)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0), FormatArgument(arg1));
	}
	internal string Format(object? arg0, object? arg1, object? arg2)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0), FormatArgument(arg1), FormatArgument(arg2));
	}

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

Today LoggerMessage.Define is a high performance logging API that aims to reduce the overhead of logging by pre-parsing format strings and parameters holes to log. Today the values are stored in a LogValues<T0, TN> struct to avoid boxing. We do all of this work only to eventually box these arguments and allocate an array to turn this into a string. We should avoid the object[] and the boxing here.

Regression?

No

Data

using System;
using Microsoft.Extensions.Logging;

namespace ConsoleApp105
{
    class Program
    {
        static void Main(string[] args)
        {
            var callback = LoggerMessage.Define<int, int>(LogLevel.Information, new(0, "Event"), "This is a {Value} and a {Score}");
            var logger = new Logger();

            Console.WriteLine("Waiting");
            Console.ReadLine();

            for (int i = 0; i < 10000; i++)
            {
                callback(logger, 1, 0, null);
            }

            Console.WriteLine("Done");
            Console.ReadLine();

        }

        public class Logger : ILogger
        {
            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }

            public bool IsEnabled(LogLevel logLevel)
            {
                return true;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            {
                var value = formatter(state, exception);
                LogToSomeplace(value);
            }

            private void LogToSomeplace(string value)
            {
                
            }
        }
    }
}

Type	Allocations	Bytes	Average Size (Bytes)
- System.Int32	20,010	480,240	24
- System.String	12,115	957,270	79.02

When I add a 3rd parameter:

Type	Allocations	Bytes	Average Size (Bytes)
- System.String	12,119	1,217,518	100.46
- System.Int32	40,010	960,240	24
- System.Object[]	10,942	642,168	58.69

Analysis

We need to implement non-allocating formatting for these calls

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

Lines 158 to 189 in 89498d8

	internal string FormatWithOverwrite(object?[]? values)
	{
	if (values != null)
	{
	for (int i = 0; i < values.Length; i++)
	{
	values[i] = FormatArgument(values[i]);
	}
	}
	return string.Format(CultureInfo.InvariantCulture, _format, values ?? Array.Empty<object>());
	}
	internal string Format()
	{
	return _format;
	}
	internal string Format(object? arg0)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0));
	}
	internal string Format(object? arg0, object? arg1)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0), FormatArgument(arg1));
	}
	internal string Format(object? arg0, object? arg1, object? arg2)
	{
	return string.Format(CultureInfo.InvariantCulture, _format, FormatArgument(arg0), FormatArgument(arg1), FormatArgument(arg2));
	}

Author:	davidfowl
Assignees:	-
Labels:	area-Extensions-Logging, tenet-performance, untriaged
Milestone:	-

[gfoidl]

As these methods go down to string.Format should this issue be based on #14484 (or other similar issues) to have a clean solution without lots of duplications?

ValueStringBuilder.AppendFormat operates on objects too, so there's not much benefit in using this type.
Special casing some common value types is another possibility, then formatting to Span. But that's a lot of duplicated and potentially outdated code once #14484, etc. are resolved.

As immediate solution one could special case the most common value-types (int, long, DateTime{Offset}, Guid) and have special code for formatting to string / Span and use the ValueStringBuilder. But this is quite a bit of effort, though.

[davidfowl]

@gfoidl See #50330 (comment). We might be able to use this implementation inside of logging.

cc @geeknoid

[davidfowl]

Did some profiling to see if we fixed this because of the new usage of CompositeFormat in the logging codebase. It turns out that we're still calling TryFormatArgumentIfNullOrEnumerable

Which boxes the incoming arguments. Seems like a trivial fix and then we can close this!