Add LoggerMessage.Define overload to disable IsEnabled check

[davidfowl]

Background and Motivation

LoggerMessage.Define allows skipping various overheads in logging (parsing the template etc) and returns delegate that performs logging and includes a check if that logging category is enabled before performing the call to log. In some cases it's important that check be moved higher up the stack to avoid transformation of parameters before calling log, for e.g.

public class Connection
{
    private string _connectionId;
    public string ConnectionId => _connectionId ??= GenerateConnectionId();
}

public static class Log
{
    private static readonly Action<ILogger, string, Exception> _connectionStart =
        LoggerMessage.Define<string>(
            LogLevel.Debug,
            new EventId(1, "ConnectionStarted"),
            "Connection {ConnectionId} started");

    public static void ConnectionStarted(ILogger logger, Connection connection)
    {
          _connectionStart(logger, connection.ConnectionId, null);
    }
}

The above logic ends up eagerly allocating the ConnectionId even when the log level isn't enabled. The code could be changed to this:

public static void ConnectionStarted(ILogger logger, Connection connection)
{
+    if (logger.IsEnabled(LogLevel.Debug))
+    {
        _connectionStart(logger, connection.ConnectionId, null);
+    }
}

It would end up checking if the category is enabled multiple times when the category is on.

Proposed API

namespace Microsoft.Extensions.Logging
{
    public static class LoggerMessage
    {
+        public static Action<ILogger, T1...T6, Exception> Define<T1...T6>(LogLevel logLevel, EventId eventId, string formatString, bool skipEnabledCheck);
    }

The ... are overloads T1 to T6 (or more).

Usage Examples

public class Connection
{
    private string _connectionId;
    public string ConnectionId => _connectionId ??= GenerateConnectionId();
}

public static class Log
{
    private static readonly Action<ILogger, string, Exception> _connectionStart =
        LoggerMessage.Define<string>(
            LogLevel.Debug,
            new EventId(1, "ConnectionStarted"),
            "Connection {ConnectionId} started",
            skipEnabledCheck: true);

    public static void ConnectionStarted(ILogger logger, Connection connection)
    {
        if (logger.IsEnabled(LogLevel.Debug))
        {
            _connectionStart(logger, connection.ConnectionId, null);
        }
    }
}

Risks

None.

[ghost]

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

Issue Details

---

Background and Motivation

LoggerMessage.Define allows skipping various overheads in logging (parsing the template etc) and returns delegate that performs logging and includes a check if that logging category is enabled before performing the call to log. In some cases it's important that check be moved higher up the stack to avoid transformation of parameters before calling log, for e.g.

public class Connection
{
    private string _connectionId;
    public string ConnectionId => _connectionId ??= GenerateConnectionId();
}

public static class Log
{
    private static readonly Action<ILogger, string, Exception> _connectionStart =
        LoggerMessage.Define<string>(
            LogLevel.Debug,
            new EventId(1, "ConnectionStarted"),
            "Connection {ConnectionId} started");

    public static void ConnectionStarted(ILogger logger, Connection connection)
    {
          _connectionStart(logger, connection.ConnectionId, null);
    }
}

The above logic ends up eagerly allocating the ConnectionId even when the log level isn't enabled. The code could be changed to this:

public static void ConnectionStarted(ILogger logger, Connection connection)
{
+    if (logger.IsEnabled(LogLevel.Debug))
+    {
        _connectionStart(logger, connection.ConnectionId, null);
+    }
}

It would end up checking if the category is enabled multiple times when the category is on.

Proposed API

namespace Microsoft.Extensions.Logging
{
    public static class LoggerMessage
    {
+        public static Action<ILogger, T1...T6, Exception> Define<T1...T6>(LogLevel logLevel, EventId eventId, string formatString, bool skipEnabledCheck);
    }

The ... are overloads T1 to T6 (or more).

Usage Examples

public class Connection
{
    private string _connectionId;
    public string ConnectionId => _connectionId ??= GenerateConnectionId();
}

public static class Log
{
    private static readonly Action<ILogger, string, Exception> _connectionStart =
        LoggerMessage.Define<string>(
            LogLevel.Debug,
            new EventId(1, "ConnectionStarted"),
            "Connection {ConnectionId} started",
            skipEnabledCheck: true);

    public static void ConnectionStarted(ILogger logger, Connection connection)
    {
        if (logger.IsEnabled(LogLevel.Debug))
        {
            _connectionStart(logger, connection.ConnectionId, null);
        }
    }
}

Risks

None.

Author:	davidfowl
Assignees:	-
Labels:	api-suggestion, area-Extensions-Logging, untriaged
Milestone:	-

[bartonjs]

Video

Looks good as proposed.

namespace Microsoft.Extensions.Logging
{
    public static class LoggerMessage
    {
        public static Action<ILogger, T1, Exception> Define<T1>(LogLevel logLevel, EventId eventId, string formatString);
        public static Action<ILogger, T1, T2, Exception> Define<T1, T2>(LogLevel logLevel, EventId eventId, string formatString);
        public static Action<ILogger, T1, T2, T3, Exception> Define<T1, T2, T3>(LogLevel logLevel, EventId eventId, string formatString);
        public static Action<ILogger, T1, T2, T3, T4, Exception> Define<T1, T2, T3, T4>(LogLevel logLevel, EventId eventId, string formatString);
        public static Action<ILogger, T1, T2, T3, T4, T5, Exception> Define<T1, T2, T3, T4, T5>(LogLevel logLevel, EventId eventId, string formatString);
        public static Action<ILogger, T1, T2, T3, T4, T5, T6, Exception> Define<T1, T2, T3, T4, T5, T6>(LogLevel logLevel, EventId eventId, string formatString);
    }
}

[gfoidl]

@bartonjs did you copy the wrong overloads? These are already here:

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

Line 151 in 5078dd6

public static Action<ILogger, T1, Exception?> Define<T1>(LogLevel logLevel, EventId eventId, string formatString)

(except the nullability on Exception) and miss the proposed argument skipEnabledCheck.

What about the overload that doesn't take any T1...T6?

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

Line 130 in 5078dd6

public static Action<ILogger, Exception?> Define(LogLevel logLevel, EventId eventId, string formatString)

---

PS: I have a PR ready, just need to submit it when the new overloads are confirmed.

[KalleOlaviNiemitalo]

PS: I have a PR ready, just need to submit it when the new overloads are confirmed.

Renaming "master" to "main" in #48357 broke the link. https://github.com/dotnet/runtime/compare/main...gfoidl:loggermessage-skipEnabledCheck?expand=1 works instead.

You added skipEnabledCheck checks inside each lambda expression. This could cause a minor slowdown in every logging call but I don't know whether it will be measurable. If a benchmark shows that it is indeed slower, then an alternative would be to do the check outside the lambda expression:

            if (skipEnabledCheck)
            {
                return (logger, exception) => { /* just call logger.Log and not logger.IsEnabled */ };
            }
            else
            {
                return (logger, exception) => { /* call logger.IsEnabled and logger.Log */ };
            }

That would be more work for the JIT compiler, though.

[davidfowl]

I would prefer if it returned a different lambda without the check. @KalleOlaviNiemitalo are you going to submite a PR?

[KalleOlaviNiemitalo]

No, I do not intend to make a PR.

[gfoidl]

But I can take the suggestion from @KalleOlaviNiemitalo and incorporate them into my changes.

[gfoidl]

Filed dotnet/aspnetcore#31332 so that these new API can be used for ASP.NET Core too.