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

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.

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

Lines 110 to 116 in 67d74fc

	return (logger, arg1, exception) =>
	{
	if (logger.IsEnabled(logLevel))
	{
	Log(logger, arg1, exception);
	}
	};

LoggerMessage also makes it harder to list arguments in the wrong order as in #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.