Logging-Generator should allow to skip the IsEnabled check

[gfoidl]

Taking the example from #45290 and bring it to the logging-generator:

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

    private string GenerateConnectionId() => Guid.NewGuid().ToString();    // or something more expensive
}

public static partial class Log
{
    public static void ConnectionStarted(this ILogger logger, Connection connection)
    {
        if (logger.IsEnabled(LogLevel.Debug))
        {
            ConnectionStarted(logger, connection.ConnectionId);
        }
    }

    [LoggerMessage(EventId = 1, EventName = "ConnectionStarted", Level = LogLevel.Debug, Message = "Connection {ConnectionId} started")]
    private static partial void ConnectionStarted(this ILogger logger, string connectionId);
}

The key-point of the logger.IsEnabled check is to avoid the creation of a expensive resource if not needed.

The generated code looks like (simplifyed some names, to make it easiert to read):

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

    private static partial void ConnectionStarted(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String connectionId)
    {
        if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Debug))
        {
            __ConnectionStartedCallback(logger, connectionId, null);
        }
    }
}

So in LoggerMessage.Define true is passed in to skip the IsEnabled-check, which is good.
But in the "logging method" IsEnabled is checked, regardless if our code already checked it.

Note: the IsEnabled check isn't free either, I'll defer to @davidfowl's comment: #50334 (comment)

Thus I propose to extend

[AttributeUsage(AttributeTargets.Method)]
public sealed class LoggerMessageAttribute : Attribute
{
    public LoggerMessageAttribute() { }
    public int EventId { get; set; } = -1;
    public string? EventName { get; set; }
    public LogLevel Level { get; set; } = LogLevel.None;
    public string Message { get; set; } = "";
+   public bool SkipEnabledCheck { get; set; } = false;
}

so the above example could be written as:

public static partial class Log
{
    // ...

    [LoggerMessage(EventId = 1, EventName = "ConnectionStarted", Level = LogLevel.Debug, Message = "Connection {ConnectionId} started", SkipEnabledCheck = true)]
    private static partial void ConnectionStarted(this ILogger logger, string connectionId);
}

and the generated code to be like:

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

    private static partial void ConnectionStarted(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String connectionId)
    {
        __ConnectionStartedCallback(logger, connectionId, null);
    }
}

That way IsEnabled is checked only once, if the user is aware of that pattern and opts-into this behaviour.

/cc: @maryamariyan

---

PS: should this be a formal api proposal? I didn't chose that template, as this api isn't shipped public

[ghost]

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

Issue Details

---

Taking the example from #45290 and bring it to the logging-generator:

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

    private string GenerateConnectionId() => Guid.NewGuid().ToString();    // or something more expensive
}

public static partial class Log
{
    public static void ConnectionStarted(this ILogger logger, Connection connection)
    {
        if (logger.IsEnabled(LogLevel.Debug))
        {
            ConnectionStarted(logger, connection.ConnectionId);
        }
    }

    [LoggerMessage(EventId = 1, EventName = "ConnectionStarted", Level = LogLevel.Debug, Message = "Connection {ConnectionId} started")]
    private static partial void ConnectionStarted(this ILogger logger, string connectionId);
}

The key-point of the logger.IsEnabled check is to avoid the creation of a expensive resource if not needed.

The generated code looks like (simplifyed some names, to make it easiert to read):

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

    private static partial void ConnectionStarted(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String connectionId)
    {
        if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Debug))
        {
            __ConnectionStartedCallback(logger, connectionId, null);
        }
    }
}

So in LoggerMessage.Define true is passed in to skip the IsEnabled-check, which is good.
But in the "logging method" IsEnabled is checked, regardless if our code already checked it.

Note: the IsEnabled check isn't free either, I'll defer to @davidfowl's comment: #50334 (comment)

Thus I propose to extend

[AttributeUsage(AttributeTargets.Method)]
public sealed class LoggerMessageAttribute : Attribute
{
    public LoggerMessageAttribute() { }
    public int EventId { get; set; } = -1;
    public string? EventName { get; set; }
    public LogLevel Level { get; set; } = LogLevel.None;
    public string Message { get; set; } = "";
+   public bool SkipEnabledCheck { get; set; } = false;
}

so the above example could be written as:

public static partial class Log
{
    // ...

    [LoggerMessage(EventId = 1, EventName = "ConnectionStarted", Level = LogLevel.Debug, Message = "Connection {ConnectionId} started", SkipEnabledCheck = true)]
    private static partial void ConnectionStarted(this ILogger logger, string connectionId);
}

and the generated code to be like:

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

    private static partial void ConnectionStarted(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String connectionId)
    {
        __ConnectionStartedCallback(logger, connectionId, null);
    }
}

That way IsEnabled is checked only once, if the user is aware of that pattern and opts-into this behaviour.

/cc: @maryamariyan

---

PS: should this be a formal api proposal? I didn't chose that template, as this api isn't shipped public

Author:	gfoidl
Assignees:	-
Labels:	area-Extensions-Logging, untriaged
Milestone:	-

[davidfowl]

It should be doing this by default AFAIK. The if check should always be in the generated code.

[gfoidl]

The if check should always be in the generated code.

Currently it is, but I'd like to get rid of it to avoid the double-check.

[davidfowl]

Oh I thought it was skipping already, I don't think it should be an option, just always skip the check.

[gfoidl]

just always skip the check.

Agree.
But it should be an option, so that it can be passed to LoggerMessage.Define.

From the proposal above we could get these cases:

SkipEnabledCheck = false

skipEnabledCheck: false passed to LoggerMessage.Define then there's the check for IsEnabled.

SkipEnabledCheck = true

skipEnabledCheck: true passed to LoggerMessage.Define so that there's no check for IsEnabled, and the user is responsible for checking that.

The Generated code will in all cases look like:

partial class Log
{
    private static readonly Action<ILogger, string, Exception?> __ConnectionStartedCallback =
        LoggerMessage.Define<string>(LogLevel.Debug, new EventId(1, "ConnectionStarted"), "Connection {ConnectionId} started", /* value from the SkipEnabledCheck property */);

    private static partial void ConnectionStarted(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String connectionId)
    {
        __ConnectionStartedCallback(logger, connectionId, null);
    }
}

[davidfowl]

I don't think so. It's always better to turn it off and generate the if directly so that that check can be inlined into the caller. The check inside of the delegate call can't be inlined into the caller (the JIT can't see though delegates yet).

[gfoidl]

Then we are back to the initial proposal (top comment).

If the user-code already has a logger.IsEnabled check, so the generated code shouldn't check it again.

[davidfowl]

Ah that makes sense now

[gfoidl]

@maryamariyan re your question #50334 (comment)
(I can't answer over there nor in the issue that the PR fixes, as it's closed, so here).

did you find micro benchmark use cases for which adding a skipEnabledCheck would have improved performance?

It saves the interface dispatch and the compare. This shows up in a micro-benchmark (see below).
For more real world scenarios, where several logging sink are used, this saving is even greater, as a linear search over the message loggers is done (though to be fair: the more work the loggers need to do, the less this won't show up).
But the biggest gain comes from a scenario like the one from the top comment (here). logger.IsEnabled is checked before creating a costly object, and without skipEnabledCheck logger.IsEnabled needs to re-evaluated at the call to logging. That's not necessary.

For a trivial benchmark:

|           Method |     Mean |   Error |   StdDev | Ratio | RatioSD |  Gen 0 | Gen 1 | Gen 2 | Allocated |
|----------------- |---------:|--------:|---------:|------:|--------:|-------:|------:|------:|----------:|
|          Default | 255.5 ns | 5.14 ns | 12.70 ns |  1.00 |    0.00 | 0.0329 |     - |     - |     104 B |
| SkipEnabledCheck | 229.4 ns | 4.54 ns |  8.53 ns |  0.89 |    0.05 | 0.0331 |     - |     - |     104 B |

Code

using System;
using System.Runtime.CompilerServices;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Running;
using Microsoft.Extensions.Logging;

BenchmarkRunner.Run<Bench>();

[MemoryDiagnoser]
public class Bench
{
    private readonly ILogger _logger;
    private string _name = "Batman";
    private int _age = 82;

    public Bench()
    {
        _logger = LoggerFactory.Create(builder =>
        {
            builder.ClearProviders();
            builder.AddProvider(new MyLoggerProvider());
        }).CreateLogger(typeof(Bench));
    }

    [Benchmark(Baseline = true)]
    public void Default() => Log.Log0(_logger, _name, _age);

    [Benchmark]
    public void SkipEnabledCheck() => Log.Log1(_logger, _name, _age);

    private static class Log
    {
        private static readonly Action<ILogger, string, int, Exception?> s_log0 = LoggerMessage.Define<string, int>(
            LogLevel.Information,
            new EventId(1001),
            "Name {Name} is {Age} years old");

        private static readonly Action<ILogger, string, int, Exception?> s_log1 = LoggerMessage.Define<string, int>(
            LogLevel.Information,
            new EventId(1001),
            "Name {Name} is {Age} years old",
            skipEnabledCheck: true);

        public static void Log0(ILogger logger, string name, int age) => s_log0(logger, name, age, null);
        public static void Log1(ILogger logger, string name, int age) => s_log1(logger, name, age, null);
    }
}

public class MyLogger : ILogger
{
    public IDisposable BeginScope<TState>(TState state) => throw new NotImplementedException();
    public bool IsEnabled(LogLevel logLevel) => true;
    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        => LogCore(formatter(state, exception));

    [MethodImpl(MethodImplOptions.NoInlining)]
    private static void LogCore(string _) { }
}

public class MyLoggerProvider : ILoggerProvider
{
    public ILogger CreateLogger(string categoryName) => new MyLogger();
    public void Dispose() { }
}

<Project Sdk="Microsoft.NET.Sdk">

    <PropertyGroup>
        <OutputType>Exe</OutputType>
        <TargetFramework>net6.0</TargetFramework>
        <Nullable>enable</Nullable>
    </PropertyGroup>

    <ItemGroup>
        <PackageReference Include="BenchmarkDotNet" Version="0.12.1" />
        <PackageReference Include="Microsoft.Extensions.Logging" Version="6.0.0-preview.5.21267.12" />
    </ItemGroup>

</Project>

Note: the allocations in the benchmark come from boxing, this is tracked in #50768

[bartonjs]

Video

Looks good as proposed

namespace Microsoft.Extensions.Logging
{
    [AttributeUsage(AttributeTargets.Method)]
    public sealed class LoggerMessageAttribute : Attribute
    {
        public LoggerMessageAttribute() { }
        public int EventId { get; set; } = -1;
        public string? EventName { get; set; }
        public LogLevel Level { get; set; } = LogLevel.None;
        public string Message { get; set; } = "";
+       public bool SkipEnabledCheck { get; set; } = false;
    }
}

[gfoidl]

#54305 got merged, so this one is done --> closing.