Allocation-free logging for disabled log levels

[mikernet]

I think there should be allocation-free extension methods for disabled log levels. Right now calls to Log always allocate an array and box values which makes it very expensive for trace level calls. This is fine if the log is enabled, but a call to log a disabled log level should have minimal impact on performance.

A set of extension methods following this pattern would solve the problem:

public static void LogTrace<T>(this ILogger logger, Exception exception, string message, T arg)
{
    if (logger.IsEnabled(LogLevel.Trace))
        logger.Log(LogLevel.Trace, exception, message, arg);
}

public static void LogTrace<T1, T2>(this ILogger logger, Exception exception, string message, T1 arg1, T2 arg2)
{
    if (logger.IsEnabled(LogLevel.Trace))
        logger.Log(LogLevel.Trace, exception, message, arg1, arg2);
}

public static void LogTrace<T1, T2, T3>(this ILogger logger, Exception exception, string message, T1 arg1, T2 arg2, T3 arg3)
{
    if (logger.IsEnabled(LogLevel.Trace))
        logger.Log(LogLevel.Trace, exception, message, arg1, arg2, arg3);
}

Is there an appetite for a PR for this? If so, I'll happily take it. If not, I'll just build these into my own library.

[WestDiscGolf]

I was looking at this yesterday after a discussion at work. The fact that under the hood everything calls into FormattedLogValues when using the extension methods is very odd. Especially when the log level is disabled. It was raised in a code review as in the past the max no. of cache formatters has been reached, yet putting a if (logger.IsEnabled(LogLevel.Debug)) on all calls to LogDebug() seems to add, what should be, pointless noise to the code.

[mikernet]

Just FYI, in case you happen to be using Fody, there is always this :) https://github.com/wazowsk1/LoggerIsEnabled.Fody

[ghost]

Tagging subscribers to this area: @tarekgh, @tommcdon Notify danmosemsft if you want to be subscribed.

[tarekgh]

CC @maryamariyan

[daredever]

There is another way to implement this feature, see my repo's dev branch PerformanceLogging. The main idea is to add extensions to ILogger:

public static LogWithLevel? Trace(this ILogger logger) => 
    LogWithLevel.CreateIfEnabled(logger, LogLevel.Trace);

public static LogWithLevel? Debug(this ILogger logger) => 
    LogWithLevel.CreateIfEnabled(logger, LogLevel.Debug);

and create a special struct:

public readonly struct LogWithLevel
{
    private readonly ILogger _logger;
    private readonly LogLevel _logLevel;

    private LogWithLevel(ILogger logger, LogLevel logLevel)
    {
        _logger = logger;
        _logLevel = logLevel;
    }

    /// <summary>
    /// Creates <see cref="LogWithLevel"/> only if provided level for given logger is enabled.
    /// </summary>
    /// <returns>
    ///   struct <see cref="LogWithLevel"/>(<paramref name="logger"/>, <paramref name="logLevel"/>)
    ///   if log is enabled for given level; null otherwise
    /// </returns>
    public static LogWithLevel? CreateIfEnabled(ILogger logger, LogLevel logLevel) =>
        logger?.IsEnabled(logLevel) != true ? (LogWithLevel?) null : new LogWithLevel(logger, logLevel);

    public void Log(EventId eventId, Exception exception, string message, params object[] args) =>
        _logger.Log(_logLevel, eventId, exception, message, args);

    public void Log(EventId eventId, string message, params object[] args) =>
        _logger.Log(_logLevel, eventId, message, args);

    public void Log(Exception exception, string message, params object[] args) =>
        _logger.Log(_logLevel, exception, message, args);

    public void Log(string message, params object[] args) =>
        _logger.Log(_logLevel, message, args);
}

after that we'll have shortcuts below:

logger.Trace()?.Log("Message.");
logger.Debug()?.Log($"Message: {GetMessage()}.");

Repo contains several benchmarks. In dev infrastructure there is 5-10% performance decrease on double log level checking, but in production with MinLogLevel = LogLevel.Info performance increase up to 95% without any unnecessary allocations in heap.

But we should change current API at ILogger extensions.

[daredever]

сс @korifey

[KalleOlaviNiemitalo]

There is already LoggerMessage, whose methods return delegates that try to avoid allocating. It is less convenient to use than LoggerExtensions, though. https://github.com/dotnet/runtime/blob/67d74fca70d4670ad503e23dba9d6bc8a1b5909e/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerMessage.cs#L110-L116

LoggerMessage also makes it harder to list arguments in the wrong order as in https://github.com/dotnet/runtime/issues/37862.

[daredever]

There is already LoggerMessage, whose methods return delegates that try to avoid allocating. It is less convenient to use than LoggerExtensions, though.

We should define logger message for each log entry template. Mostly it is very hard to do, and we'll use $"my log {message} with {id}" and provide in action. So logger message is a good thing, but there may be easier way for logging.

[davidfowl]

Right, LoggerMessage is the pattern for this and it’s even documented https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/loggermessage?view=aspnetcore-3.1

I wouldn't try to optimize the easy mode logging as it isn't meant to be used for high performance logging

[daredever]

@davidfowl if you speak about client code, I agree with you, we can control logging. But what will we do with third-party libs in this case? Please, look at these examples https://github.com/dotnet/orleans/search?q=logger.Trace Code works fine only with boilerplate. Generic extensions like in issue description can do better all apps in one time :)

[mikernet]

The LoggerMessage pattern is both more tedious to work with and slower than the aforementioned extension methods, which adds up when you have deep logging in an embeddable database engine. Those extension method calls will usually get inlined so not only do you not have the impact of a delegate call but no method call overhead either. It effectively behaves exactly as if you called if (logger.IsEnabled(LogLevel.Trace)) directly from your code.

[davidfowl]

@daredever some of those aren't even the right ILogger. Those can be changed to use the more performant pattern.

@mikernet do you have profiles? The extension methods that directly take the string have a couple of known overheads:

• They end up parsing the format string once the cache limited is hit (1024 entries).
• They end up boxing the values

There's delegate overhead for sure but I'd be surprised if that overshadowed the other costs.

That said, I do think the source generator here solves both problems, making it both easier to consume and cheap by using code generation removing the extra delegate call https://github.com/dotnet/runtime/issues/36022

[mikernet]

I'm talking about my proposed extension methods in the OP, which does not box any values (if the log level is disabled). If the logging level is enabled I'm not concerned about the format string cache or boxing, I'm more concerned about perf for disabled log levels.

Serializing data composed of "simple values" (i.e. a bunch of int fields) get a 15% throughput boost from avoiding the delegate calls, less for data that has more complex values that require more work per value.

[davidfowl]

So the goal of the above overloads is to avoid the boxing of value types but not the overhead of the parsing the format string right?

[davidfowl]

I also see it's calling some underlying log method which itself is generic and takes many generic arguments, what method is that?

[daredever]

I see these problems if log level is disabled in app:

• new objects array of params in current implementation of extensions
• boxing of value types and they will not be logged
• cache used for unnecessary strings, and mostly it will be trace and debug logs

the method is from https://github.com/dotnet/runtime/blob/master/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerExtensions.cs

[mikernet]

@davidfowl

avoid the boxing of value types but not the overhead of the parsing the format string right?

Yes, avoids boxing if the log level is disabled and the delegate call overhead that happens every time the LoggerMessage action is invoked which checks if it is enabled or not. The underlying method call that it makes inside the if when the log level is enabled will box in this case, but usually I am more concerned about disabled log levels having as small an impact on performance as possible.

[davidfowl]

@mikernet the underlying method doesn't exist so it somehow needs to map to a call to ILogger.Log. So it needs to parse the format string and create a struct that represents the format string, it's arguments and the formatted text.

I'd much prefer if we focus on the approach described here https://github.com/dotnet/runtime/issues/36022#issuecomment-734960964. It's much cleaner and makes logger more pleasant and performant.

[mikernet]

I don't understand what you are saying. It does map to ILogger.Log. The parsing, formatting, etc only happens if the log level is enabled, which makes this faster for disabled log levels.

@daredever pointed to where the underlying Log method is - Microsoft.Extensions.Logging.Abstractions.LoggerExtensions. It's just the normal logging methods that take params object[] args which currently exist.

[mikernet]

The generator approach is fine if you want to write out a method for each type of log message, but this would be a strict improvement over the extension methods currently available in LoggerExtensions for "easy mode" logging.