You are doing .NET logging wrong. Let's fix it

For those wondering, LoggerMessage.Define was left out intentionally because it's its own video coming soon-ish.

Very helpful video. Thanks Nick!

Amazing explanation, even I as a noob feel i got the gist of it
Thanks a ton again, cheers

It would be great if you specified the decision developers need to make when implementing logging on an API, vs. a Server sln, vs. a Wasm sln etc.

how do you implement dependency injection of ILogger into DurableTask.Core orchestrations and task activities?

I think string interpulation works differently now, I’ve seen it turned into numbered templates as well as an object array

Great video!

Really intresting! This is something we have been dicussing in my work place projects. Before viewing this video we settled on using extension methods (IfTrace,IfDebug,IfInfo) and Null-conditional to implment single line logging: _logger?.IfDebug()?.Debug("Test message is: {0}, message); I would value your thoughts on this approach.

I am using the Roslyn Analyzer to just insert the if statements around my log methods. So I don't have to have an adapter, and so stack traces are cleaner.

"your going to be blinded in 3,2,1 now!" Ha ha ha

Is this still relevant currently? Kinda stupid if ms still havent optimize this in the box

That's bad. Really bad. I just don't even remember how to use parameter approach instead of the modern string interpolation. Sad about this.

Awesome video, but you doing logging wrong. All ms extenstions bullshit is bullshit and slow. Why? Because it doing wrong. Why? Because it pretend to general solution but actually can handle only stupid web app scenarios where speed is not a factor at all. Effective logging never can be done via virtual call. Period.

Great video. Thanks!

out of infinte possibilities of numbers in the spectrum he chooses 69 and 420, you got my respect @NickChapsas

Wandering why microsoft didn't place generic overloads right in ILogger. "Six parameters is enough for all! If you want more use unoptimised LogInfoWeird with params array"

Thanks

Hi Nick it's a great video. Do you have any source code where you broadly used Serilog. I want to implement Serilog in my learning project.

Hey Nick, really appreciate your work.

Doing some reading and StackOverflow tells me that string interpolation turns into string.Format() at run time, therefore shouldn't performance be the same between the two?

Thanks.

Thanks

This is very important, specially in production!! thank you!

You sad not use string interpolation via _loger.LogInformation( $" xxx {parameter} yyy ") in loggin because string will be allocated every time.
Was it fixed in C# 10 and CORE 6.0 ?

Dziękujemy.

123K Subs.. :)

ωραίος!

Interesting video. However I'm not sure I understood your point about using the generic arguments vs the params array. In these two cases both loggers had an if enabled check around them and the params one took 4ns and the generics one took 9ns. You said that this time difference does not matter (sure its tiny) and that the fact the generics one did not use memory makes up for this. However the params one did not use memory either. So as the params one was faster, why is it not preferred?

Whats this obssession with the 69 number 😂👍

I always thought that logging, as is a I/O task (when saving to a file or a db), it would be better to perform it on a different thread. Something simple like Task.Parallel(DoLog()), that way the execution flow will continue and it's not waiting for the I/O task to be complete.

"Throw in a couple random things..." uses 69 and 420 "random" indeed. 😆

Great stuff Nick. But why is this not already build-in in the .NET Logger Class??? 🧐

69 and 420 😎

i don't do logging hahahaha

Upvote for double blind Nick Chapsas! Long days in the office? Remember to take care of yourself!

One problem with your demonstration here, you don't account for optimization.
If you build a for-loop that only has if false in it, it will simply get optimized away, this is why you some things like 100000 faster execution with the if.
This is a situation that is almost impossible to encounter since when would you log a variable that is created in the logger call.
To fix this assign the variable before you do the check for the log level, this would simulate your original case from the Controller.

But other than that a very good video, was very surprised moving from Serilog to Log4net that this was not implemented.
Good usage of dotTrace as well.

Can you make a video like "evolution of how to declare a property"?
I would like to show my colleagues all the ways they have available to declare a property.

I'm not doing .NET logging at all!

Thanks! This is great stuff. Also, I kind of like your choice of numbers..

If your benchmark is pure logging calls it distorts the impact of logging. In a real world app that actually does work and if the logging is 0.5% performance hit - do we care?

"So, lets just have a couple of random things over here"... adds "69" and "420"... nice to know I'm not alone lol

Which logging library is this? Seems like a good reason to use a better logging library with better method overloads which pass without that dynamic array, at least for majority use cases.

Apart from the performance gain templates allows logging providers to implement semantic or structured logging. We use sentry to capture warnings and errors. It will create tags for each of the arguments. It also uses the message tempate without all the noise from the arguments to group the logs. It makes the logs much easier to navigate.

Thank you for the video. I've never thought the built-in logger is so inefficient.

Do you know if the time measured in the benchmark is including the time used for garbage collection?

Hey Nick, good material as always.

Coming back to the actual performances, I think you may try something like (sorry for the formatting, I didn't use an IDE 😊):



public class LoggerAdapterImproved<T> : ILoggerAdapter<T>
{

private readonly Action<string> _logAction0;
private readonly Action<string, string> _logAction1;
private readonly ILogger<T> _logger;

public LoggerAdapterImproved(ILogger<T> logger)
{
_logger = logger;
if (logger.IsEnabled(LogLevel.Information))
{
_logAction0 = _ => _logger.LogInformation(_);
_logAction1 = (_, __) => _logger.LogInformation(_, __);
}
else
{
_logAction0 = _ => { };
_logAction1 = (_, __) => { };
}

}

public void LogInformation(string message)
=> _logAction0(message);

public void LogInformation(string message, string replace1)
=> _logAction1(message, replace1);
}

Clearly, it doesn't take into account the possibility of changing the log level at runtime, but I usually prefer an 'immutable' approach.

With this setup constantly get a 3.5x faster implementation, still preserving the testability.

Keep going and send a hug to my friend Stefano G 😉