If performance of logging is important log messages should go to FIFO queue first and then picked up by background thread. That introduces small delay in reporting messages to the file but guarantees clients won't be affected by slowness of logging subsystem. And I will just say this: memory is cheap.
Back in the old days, I learned to do logging with the Debug class. The advantage I was told about was that any line made with that would simply not be there in the Release version. Althought this doesn't allow me to turn on debug logging in a Release environment, and I only have 2 levels, it is by far the most efficient way to get rid of debug logging in an Release environment. I like knowing my relics.
Thanks for sharing your knowledge with the community, Nick. Awesome videos. Purchased your bundle just to support what you do on TH-cam. Please keep it up
Thank you! I couldn't understand why VS began to throw errors at me. I tried to read the link, and actually managed to implement this Logger Definition in a static class and use it, but didn't fully understand why. I do now. Excellent explanation, thanks so much
Would you consider doing a video on when and how to do logging? Would it be normal to have every second line of an otherwise easy to read method logging something?
Thank for the video but I'm actually a little lost. You demonstrate the best way to do it, but how do you implement it in a project ? When you log, for exemple, methods, they have not always the same parameters. So maybe I miss something but each time you want log a new method with new parameters or with a different log message, you need to create a new method with LoggerMessage Attribut ?
I wanted to "abuse" the logger for (thread safe) writing data to a log-file. I was VERY! surprised to see that .NET Core does NOT support writing to log-files out of the box.
It's a shame that NLog doesn't work particularly well with the past two videos you've created. The "callsite" ends up being the extension method name in the log file, so everything looks like it's coming from the same code. I'm using NLog with DI, and as a result I am still working with ILogger but I can't quite seem to keep the original callsite from extension methods.
Be careful with those async sinks though. I find them somewhat unreliable in some situiations, such as when your app crashes or fails to start, often due to a configuration issue. When you have a config issue, you may not even get to the point where the publisher of the async sink starts, in which case it's as though you didn't have any logs at all. It won't really help figuring out what the cause is, and the fact that configs tend to be env-dependend makes it worse, as you may only experience the issue on production. Second, crashes can also be tough to diagnose with them, because the publisher pushes the log entries periodically, so any failure in your app which kills it altogether prevents it from being able to send the logs to your log store, which is key to identifying what the actual problem is. Stdout logging has none of these issues, as it survives a crash of your app - anything written to stdout will still be there even after the app has terminated, which makes it easy to collect the logs after a failure. It also is alive as soon as your app is, so startup failure logs are super easy to capture as well.
I like how you pretty much reached performance perfection here, but the amount of trade offs make me think I could only use this in cases where I have already written and can easily find the exact log function that I need. I would think that any situation where performance would be important enough to necessitate writing a new log function is probably a place where the log would grow way too large to be useful anyways. Most of all, I really just want to be able to use all the bells and whistles of string interpolation. What are your thoughts on the performance improvements of C#10 string interpolation? (My replies keep getting deleted, not sure if it is some sort of problem with TH-cam or some other issue... you can handle the string interpolation yourself which allows you to structure your data however you like. This can be done with FormattableString or InterpolatedStringHandler, which also opens the door for similar performance optimizations to the ones in your video.)
You should never use string interpolation in logging. It doesn't matter that it's performance was improved. The problem was never the string interpolation performance. You would have the same problem with string concatenation. The problem is that you lose the benefits of structured logging.
quick question: from your experience when going for source-generated logging, how would you maintain a collection of source-generated events for a large-scale application?
Dont you take the power of writing whatever message necessary in the method Log...(string message)? now you have the string template in the extension method, so you need to create different type of methods for your different LogLevel x different parameters x different messages right?
why is using static action faster than just calling same code right in the extension method? Is it because of generic method Define which is implemented this way only once when code runs?
Good to know but If I had to log a thousand of message, I need to create a thousand of extensions methods and, depending on how many parameters to use in the string message, this can be a little confusing... I mean, it's not so easy to understand what you are really logging, you need to go in the extension method itself and read it.
How did you get your partial static void method to work, Visual Studio complains about CS8795 Partial method must have an implementation part because it has accessibility modifiers? Great video by the way.
@@nickchapsas Yeah copied your code exactly, looking at it more it appears to be a bug with VS2022, the error is there but you can compile and run, the only way to get the error to go is to restart VS.
Recently came across the delegate approach when I migrated an app to .NET 6. To be honest, I'm not sold. I appreciate it's easier on allocations but it feels like such a backwards approach.
@@nickchapsas absolutely agree. We implemented the delegate approach today in a PR and decided to revert back to the extension method approach. We took into consideration that we're not developing performance critical apps. Regardless, thank you for sharing this content.
Hey nick, your videos are great..! In one of your videos you showed how to inject a class that inherits an interface and also same interface is injected in constructor. I have a similar situation. Can you help me find that video. It would be great 👍. Thanks..!
Thanks Nick! Can you also give some insights on how to best optimise on the logger calls that writes to file, as the I/O calls normally slows down the code.
Typically... you don't. A proper logging libary uses a buffered writer and flushes either periodically, when the buffer is full, or when the application shuts down. Log-Calls also never really block, as they are often just "push this message into a queue" methods and don't directly write to an output. There is a threadpool thread that handles the writing (or multiple, depending on the implementation, sinks, etc.).
Nick, I have a doubt in this video and in the previous about logging adapter, you say adapter without if on the benchmark but you have the if in the implementation.. 🤷♂️
@@nickchapsas I still think it appeared a bit faster with the Level check and without. Does the global:: syntax have any perf gain or optimization behind the scenes?
@@nickchapsas But it is still faster with the library version with the if check, and even faster when the if check is not there in the library code according to your benchmark. If that's only a benchmark inaccuracy then maybe you should try to eliminate contributing factors to these inaccuracies (like closing all other apps while running the benchmark, forcing runs on the same thread, disable turbo, etc.). It is quite misleading this way.
I hate how the Brazilian currency is weak compared to the pound... The Brazilian minimum wage is approximately 159 pounds... per month This makes their courses very expensive for the Brazilian reality. btw you are awesome.
Why not just set the LoggerAdapter property to null and use LoggerAdapter?.LogInformation(). Or use polymorphism and have a NullLogger where calling LoggerAdapter.LogInformation() does nothing?
@@br3nto Because you're relying on something that if left unhandled can throw and break your application's flow. You're putting too much faith on something volatile and someone who reads the code without context can be incredibly confused.
i wanted to leave a really silly comment like "i gave your mum some high performance logging", but i realised i am far to old to be making such inane jokes... so i wont leave that comment.
Thanks for the video. I was curious if the extension method was part of the "magic" since you implemented it that was and so does Microsoft in the documentation. Ran my own benchmarks and unless I'm missing something there is no appreciable benefit from implementing the extension method vs. calling the action directly. This is good for me as the extension method doesn't really make sense for one off log calls (ie: request logging in an IMiddleware). | Method | Logger | Mean | Error | StdDev | Median | Ratio | RatioSD | Gen 0 | Allocated | |------------------------ |------------ |-------------:|-----------:|-----------:|-------------:|------:|--------:|-------:|----------:| | LoggerMessage_Action | Serilog [W] | 8.290 ns | 0.1812 ns | 0.1779 ns | 8.212 ns | 0.09 | 0.00 | - | - | | LoggerMessage_Extension | Serilog [W] | 8.092 ns | 0.1143 ns | 0.1069 ns | 8.071 ns | 0.09 | 0.00 | - | - | | Logger_LogInformation | Serilog [W] | 92.322 ns | 1.7557 ns | 1.7243 ns | 91.717 ns | 1.00 | 0.00 | 0.0153 | 64 B |
The extension method has nothing to do with performance and everything to do with giving meaningful names to what you're about to log. If you find it cleaner/clearer to call the action directly then go for it.
@@nickchapsas thanks for confirming. That was my assumption and what 8 validated. When I watched the video again I saw that you did say the extension method was not needed but made it more convenient. The "why" it was more convenient was the part I was missing. In my request logging example an instance class method provided the same convenience of describing the parameters without the need to expose a one off logging call to the rest of the app. In any case keep up the great work, I really enjoy your videos.
Found your channel when i was looking into clean architecture and have been hooked ever since. Thanks for helping make us all better developers
If performance of logging is important log messages should go to FIFO queue first and then picked up by background thread. That introduces small delay in reporting messages to the file but guarantees clients won't be affected by slowness of logging subsystem. And I will just say this: memory is cheap.
Back in the old days, I learned to do logging with the Debug class. The advantage I was told about was that any line made with that would simply not be there in the Release version. Althought this doesn't allow me to turn on debug logging in a Release environment, and I only have 2 levels, it is by far the most efficient way to get rid of debug logging in an Release environment.
I like knowing my relics.
It is exceptionally slow while active, though.
Thanks for sharing your knowledge with the community, Nick. Awesome videos. Purchased your bundle just to support what you do on TH-cam. Please keep it up
Thank you! I couldn't understand why VS began to throw errors at me. I tried to read the link, and actually managed to implement this Logger Definition in a static class and use it, but didn't fully understand why. I do now. Excellent explanation, thanks so much
I did not know about that source gen method.
That is brilliant.
It removes a lot of the "cumbersomness" for creating the logger extensions.
Would you consider doing a video on when and how to do logging?
Would it be normal to have every second line of an otherwise easy to read method logging something?
Logging best practices is definately a video I want to make
@@nickchapsas Where are you with that? :D
Brilliant timing, I was just working on adding extra logging to a service at work :D Cheers!
Didn't think I could be surprised by a video about logging, but there you are
Me too buddy. Great stuff
Is the optimization you mentioned in this video implemented in .NET 8?
Im really curious to know....!
Thank for the video but I'm actually a little lost. You demonstrate the best way to do it, but how do you implement it in a project ? When you log, for exemple, methods, they have not always the same parameters. So maybe I miss something but each time you want log a new method with new parameters or with a different log message, you need to create a new method with LoggerMessage Attribut ?
You would need a new method.
Awesome video I just implemented this in a new projcet we are building at work and it really had a large impact!
nunca desista do seu canal vc tem potencial
Great video, thank you for sharing!!
I wanted to "abuse" the logger for (thread safe) writing data to a log-file. I was VERY! surprised to see that .NET Core does NOT support writing to log-files out of the box.
You're a legend!! Such great videos
Very informative, thank you!
It's a shame that NLog doesn't work particularly well with the past two videos you've created. The "callsite" ends up being the extension method name in the log file, so everything looks like it's coming from the same code. I'm using NLog with DI, and as a result I am still working with ILogger but I can't quite seem to keep the original callsite from extension methods.
Nice video, it's surprising that something simple as logging is taken as-is without necessarily taking into consideration this kind of thing.
Thank you for sharing Nick!
Serilog also provides an async sink to offload the logging on a separate thread.
It's too bad garbage collections affect performance of all threads, though.
Be careful with those async sinks though. I find them somewhat unreliable in some situiations, such as when your app crashes or fails to start, often due to a configuration issue.
When you have a config issue, you may not even get to the point where the publisher of the async sink starts, in which case it's as though you didn't have any logs at all. It won't really help figuring out what the cause is, and the fact that configs tend to be env-dependend makes it worse, as you may only experience the issue on production.
Second, crashes can also be tough to diagnose with them, because the publisher pushes the log entries periodically, so any failure in your app which kills it altogether prevents it from being able to send the logs to your log store, which is key to identifying what the actual problem is.
Stdout logging has none of these issues, as it survives a crash of your app - anything written to stdout will still be there even after the app has terminated, which makes it easy to collect the logs after a failure. It also is alive as soon as your app is, so startup failure logs are super easy to capture as well.
Hi Nick, first of all this was an awesome video! But I've a question: Do I need do something like that when using Serilog?
Depends on how you are using it; if you’re using it through the Microsoft logging then yeah. If you’re doing raw Serilog ILogger then no
@@nickchapsas Is there a way to use Serilog ILogger in other class or injecting it with DI and using it ?
@@utsabshrestha277 Yeah ofc. You can simply add it in your DI container as a service and inject it in whichever class you need
@@nickchapsasNice point, but is there huge performance hit if we use Serilog instead of MS extension with logger messages?
I like how you pretty much reached performance perfection here, but the amount of trade offs make me think I could only use this in cases where I have already written and can easily find the exact log function that I need. I would think that any situation where performance would be important enough to necessitate writing a new log function is probably a place where the log would grow way too large to be useful anyways. Most of all, I really just want to be able to use all the bells and whistles of string interpolation. What are your thoughts on the performance improvements of C#10 string interpolation? (My replies keep getting deleted, not sure if it is some sort of problem with TH-cam or some other issue... you can handle the string interpolation yourself which allows you to structure your data however you like. This can be done with FormattableString or InterpolatedStringHandler, which also opens the door for similar performance optimizations to the ones in your video.)
You should never use string interpolation in logging. It doesn't matter that it's performance was improved. The problem was never the string interpolation performance. You would have the same problem with string concatenation. The problem is that you lose the benefits of structured logging.
quick question: from your experience when going for source-generated logging, how would you maintain a collection of source-generated events for a large-scale application?
Would be great if you could dive into custom serialization and deserialization.
@Nick Chapas Do you have any video related to syncing the log to logzio or grafana. We can monitor it on UI
Dont you take the power of writing whatever message necessary in the method Log...(string message)? now you have the string template in the extension method, so you need to create different type of methods for your different LogLevel x different parameters x different messages right?
Correct, but you gain the performance. Performance usually has a tradeoff and this is the one here.
i am asking myself: is this optimization still possible if you already using seriolog?
How this approach compares to using serilog in terms of performance?
why is using static action faster than just calling same code right in the extension method? Is it because of generic method Define which is implemented this way only once when code runs?
Good to know but If I had to log a thousand of message, I need to create a thousand of extensions methods and, depending on how many parameters to use in the string message, this can be a little confusing... I mean, it's not so easy to understand what you are really logging, you need to go in the extension method itself and read it.
You don't need to. They can be simple methods or cached delegates that you invoke
@@nickchapsas can you please make another video where you do this? Great content by the way 👍🏻
please make a video om this
How did you get your partial static void method to work, Visual Studio complains about CS8795 Partial method must have an implementation part because it has accessibility modifiers? Great video by the way.
Did you apply the LogMessage attribute?
@@nickchapsas Yeah copied your code exactly, looking at it more it appears to be a bug with VS2022, the error is there but you can compile and run, the only way to get the error to go is to restart VS.
Recently came across the delegate approach when I migrated an app to .NET 6.
To be honest, I'm not sold. I appreciate it's easier on allocations but it feels like such a backwards approach.
Performance sometimes comes with (subjective) drawbacks
@@nickchapsas absolutely agree. We implemented the delegate approach today in a PR and decided to revert back to the extension method approach.
We took into consideration that we're not developing performance critical apps.
Regardless, thank you for sharing this content.
Hey nick, your videos are great..! In one of your videos you showed how to inject a class that inherits an interface and also same interface is injected in constructor.
I have a similar situation. Can you help me find that video. It would be great 👍. Thanks..!
Thanks Nick! Can you also give some insights on how to best optimise on the logger calls that writes to file, as the I/O calls normally slows down the code.
Typically... you don't.
A proper logging libary uses a buffered writer and flushes either periodically, when the buffer is full, or when the application shuts down.
Log-Calls also never really block, as they are often just "push this message into a queue" methods and don't directly write to an output.
There is a threadpool thread that handles the writing (or multiple, depending on the implementation, sinks, etc.).
Nick, I have a doubt in this video and in the previous about logging adapter, you say adapter without if on the benchmark but you have the if in the implementation.. 🤷♂️
Which is fine, because the name refers to the if in the external layer not internally
@@nickchapsas ohh perfect, without the if in the caller I got it jaja!
Thx! And keep coding videos 😂
is there any git hub repo for this project?
adorei muitobom adoro seus videos sao especiais
abs
What's the difference between your handmade method and the source-gen version? Why is it faster?
Because it doesn't have the log level if check
@@nickchapsas I still think it appeared a bit faster with the Level check and without. Does the global:: syntax have any perf gain or optimization behind the scenes?
@@nickchapsas But it is still faster with the library version with the if check, and even faster when the if check is not there in the library code according to your benchmark. If that's only a benchmark inaccuracy then maybe you should try to eliminate contributing factors to these inaccuracies (like closing all other apps while running the benchmark, forcing runs on the same thread, disable turbo, etc.). It is quite misleading this way.
What is that LoggerMessageAttribute? Where can I find that?
You need the Microsoft.Extensions.Logging package
can you create courses using mongodb .. thanks
Whatever you do in life, there will always be at least one youtuber who will tell you that you're doing it wrong :P
On the other hand, would you watch a video titled "You're doing it right or at least good enough, no worries👍"? :D
@@binarybang In this case it's not even in the title, it's just one of the first things he says ;)
It's in the title of the previous video, which is what I'm referencing
Can you provide me code of this log ?
I hate how the Brazilian currency is weak compared to the pound...
The Brazilian minimum wage is approximately 159 pounds... per month
This makes their courses very expensive for the Brazilian reality.
btw you are awesome.
159 GBP per month?? What the hell?
@@nickchapsas brazilian reality is insane
@@nickchapsas sad, but true. BRL is getting every day weaker.
Sad but true....
Why not just set the LoggerAdapter property to null and use LoggerAdapter?.LogInformation(). Or use polymorphism and have a NullLogger where calling LoggerAdapter.LogInformation() does nothing?
Because null driven logic like that is an absolute horrible practice
@@nickchapsas why?
@@br3nto Because you're relying on something that if left unhandled can throw and break your application's flow. You're putting too much faith on something volatile and someone who reads the code without context can be incredibly confused.
@@nickchapsas fair enough. Though you used the polymorphism technique in your vid about branchless programming (I think). It’s a nice technique.
If you don’t log, you can’t do it wrong ;)
Nice vid. Your font is too big, we can't see all the code
Second!
First !
Only me seeing 69 and 420?
3rd!
i wanted to leave a really silly comment like "i gave your mum some high performance logging", but i realised i am far to old to be making such inane jokes... so i wont leave that comment.
WTF
Thanks for the video. I was curious if the extension method was part of the "magic" since you implemented it that was and so does Microsoft in the documentation. Ran my own benchmarks and unless I'm missing something there is no appreciable benefit from implementing the extension method vs. calling the action directly. This is good for me as the extension method doesn't really make sense for one off log calls (ie: request logging in an IMiddleware).
| Method | Logger | Mean | Error | StdDev | Median | Ratio | RatioSD | Gen 0 | Allocated |
|------------------------ |------------ |-------------:|-----------:|-----------:|-------------:|------:|--------:|-------:|----------:|
| LoggerMessage_Action | Serilog [W] | 8.290 ns | 0.1812 ns | 0.1779 ns | 8.212 ns | 0.09 | 0.00 | - | - |
| LoggerMessage_Extension | Serilog [W] | 8.092 ns | 0.1143 ns | 0.1069 ns | 8.071 ns | 0.09 | 0.00 | - | - |
| Logger_LogInformation | Serilog [W] | 92.322 ns | 1.7557 ns | 1.7243 ns | 91.717 ns | 1.00 | 0.00 | 0.0153 | 64 B |
The extension method has nothing to do with performance and everything to do with giving meaningful names to what you're about to log. If you find it cleaner/clearer to call the action directly then go for it.
@@nickchapsas thanks for confirming. That was my assumption and what 8 validated. When I watched the video again I saw that you did say the extension method was not needed but made it more convenient. The "why" it was more convenient was the part I was missing. In my request logging example an instance class method provided the same convenience of describing the parameters without the need to expose a one off logging call to the rest of the app. In any case keep up the great work, I really enjoy your videos.