LoggerExtensions performance concerns

[strohhut]

Say the log level is warning and I have the following in my code:

_logger.LogInformation("Id is {Id}", myIntId);

This creates a params array and a FormattedLogValues and boxing from int to object will occur although nothing will be logged.

Wouldn't it make more sense to provide some overloads for typical amounts of arguments like

public static void LogInformation<T1, T2>(this ILogger logger, string message, T1 arg1, T2 arg2)
{
    if (logger.IsEnabled(LogLevel.Information))
    {
        logger.Log(LogLevel.Information, 0, new FormattedLogValues(message, new object[] { arg1, arg2 }), null, _messageFormatter);
    }
}

[benaadams]

The zero allocation pattern is demonstrated in KestrelTrace.cs

[strohhut]

OK, so there are two extremes. Many allocations with LoggerExtensions (what most people will use) or minimal allocations with LoggerMessage.Define (which seems a bit hidden and the class name LoggerMessage is a bit strange for a delegate factory) that basically requires you to create and store a delegate where you would normally reuse a logger.

What about some faster ILogger extensions?

[roji]

+1 on this.

[MichaCo]

@benaadams @strohhut I actually didn't know about the LoggerMessage factory before Ben mentioned it here ~~
I tried that in some tests we are doing currently with per request logging and it was a ~20% performance increase when just logging into the void. Interesting... I agree that the logging framework should either promote that option more and make it more first class, or just do some more fancy things internally to improve the performance per default.

[muratg]

Assigning to @BrennanConroy for investigation.

cc @mikeharder

[BrennanConroy]

You can also easily avoid unneeded allocations by using

if (logger.IsEnabled(LogLevel.Information))
{
    logger.LogInformation(...);
}

[strohhut]

Yeah, that's obvious. But who wants to do that (four to five lines for every logging statement, remember a closing brace should be followed by a blank line under most circumstances)?

[davidfowl]

People that want to avoid a performance hit. We do it all over the framework. We also use LoggerMessage. These are all valid options we should document.

What does the "what about some faster ILoggerExtensions" suggestion? Is that something concrete? Do you have ideas ok how to make it better?

[roji]

@davidfowl see the original post, simply providing some generic overloads to prevent the allocation of the params array in most cases would help - it's standard practice in both logging packages and other APIs...

[davidfowl]

Let me dig up the PR where we decided against this change before. Making the extension methods check is enabled by default makes the peformancd worse when the caller checks as well. That was part of the original push back against doing so.

[roji]

Note that there are two separate proposals in the original post:

• Add generic overloads to prevent the params array allocation
• Perform an "is enabled" check immediately inside the method

The two are definitely unrelated, I personally feel the first is much more needed than the second.

[strohhut]

@davidfowl You are saying that checking IsEnabled is slower than those allocations?

But checking IsEnabled happens in the delegates created by LoggerMessage.Define. And LoggerMessage.Define is used for performance reasons as far as I understand.

[davidfowl]

Add generic overloads to prevent the params array allocation

Performance numbers would definitely help this discussion.

Here's the old PR:

#101

But checking IsEnabled happens in the delegates created by LoggerMessage.Define. And LoggerMessage.Define is used for performance reasons as far as I understand.

The problem with the extension methods that check for you is that ends up being the default. If you want to check IsEnabled yourself, you end up paying that IsEnabled cost twice (then you end up having to go out of your way to find the extension method without the IsEnabled check)

[glennc]

We have a bug on docs to increase our documentation of the other logging patterns: dotnet/AspNetCore.Docs#2810

Moving this to the discussion milestone until something we want to actually implement falls out of it.

[muratg]

We are closing this issue because no further action is planned for this issue. If you still have any issues or questions, please log a new issue with any additional details that you have.