Logging Source Code Generators

[giscus[bot]]

Logging Source Code Generators

Since .NET6 we have the possibility to define an easy way of logging common statements:
Meet Compile-time logging source generators. This article will show why we have them and how to use them. Of course a smaller benchmark will also follow.

https://steven-giesel.com/blogPost/48697958-4aee-474a-8920-e266d1d7b8fa

[mehdihadeli]

Thanks, For this article,
I have one problem when I move the public partial void LogCreateUser(User user, DateTime when); to another partial class UserCreationService, in this case compiler can't infeer the ILogger field.
I think the compiler has a bug here right now.

[mehdihadeli]

Solution is moving private ILogger _logger; field to second partial class. it is Wierid :|

[mehdihadeli]

Ah okay. Thanks for the update. Maybe it would be worth to report this back to the dotnet team!?

Yes, They have a bug here

[mehdihadeli]

I think there is an issue for that before dotnet/runtime#61547

[linkdotnet]

Ah it's freshly merged (> 1 month ago). So it will be part of .net7.
Good to hear.

Thanks for the great input @mehdihadeli love it!

[mehdihadeli]

I think, it fixed in .Net 7 :D

[ernest-morariu]

I think your benchmark compares very different things.
You say that you created a NoLog ILoogger that doen't do the actual logging, but it doesn't do the formatting of message either, and the magic of the numbers your present here comes exactly for that reason.
The function LogCreateUserBad does the formatting of the message as soon as you call it while the other two functions only forward some parameters to some "empty functions" (this is the reason they have no cost).

If you modify your NoLog as:

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
    string msg = formatter(state, exception);
}

Note that this version still doesn't do the actual logging, but it does the formatting of the messge. With this version, all the three functions perform the formatting, and here is the new/correct benchmark:

Method	Mean	Error	StdDev	Gen 0	Allocated
LogCreateUserBad	502.1 ns	4.53 ns	4.23 ns	0.1564	656 B
LogCreateUserTraditionally	632.5 ns	11.74 ns	10.98 ns	0.1717	720 B
LogCreateUser	570.6 ns	7.93 ns	7.41 ns	0.1621	680 B

The advantage of the compile time generated functions stands only in the fact they check the IsEnabled before the actual formatting and logging, so, if the current logging level is not allowed, the formatting and the loggin is avoided.
However, if IsEnabled returns True, the time cost is the same.

Now there are other ways of implementing logging that makes the function LogCreateUserBad even faster and simplier than the compile time generated functions.

[linkdotnet]

Thanks for the comment. Your reasoning might be correct and I did indeed have a completely wrong and misleading setup.

According to Microsoft itself (https://learn.microsoft.com/en-us/dotnet/core/extensions/high-performance-logging) it is not just about IsEnabled or not. And indeed, if you check the generated code - at least the whole topic around boxing is "handled by the attribute".