You are doing .NET logging wrong. Let's fix it
Vložit
- čas přidán 11. 05. 2024
- Check out the Essentials course bundle: dometrain.com/bundle/nick-cha...
Become a Patreon and get source code access: / nickchapsas
Hello everybody I'm Nick and in this video I will show you why you are probably doing .NET logging wrong and how you can fix it. Logging is a very common thing in any application and it is really easy to abuse.
Timestamps
Intro - 0:00
The problem - 1:07
Benchmarking it - 6:44
Memory profiling with dotMemory - 10:55
A pragmatic solution - 18:24
Serilog - 23:15
Don't forget to comment, like and subscribe :)
Social Media:
Follow me on GitHub: bit.ly/ChapsasGitHub
Follow me on Twitter: bit.ly/ChapsasTwitter
Connect on LinkedIn: bit.ly/ChapsasLinkedIn
Keep coding merch: keepcoding.shop
#csharp #dotnet #logging
For those wondering, LoggerMessage.Define was left out intentionally because it's its own video coming soon-ish.
What about [System.Diagnostics.Conditional] attribute? That will not compile functions if a define is not present.
@@CallumPooleProgrammer I THINK, [Conditional] will still compile the methods, it just won't execute them.
@@JonathanPeel Yes, the methods will still be compiled, but all calls to them will be stripped, including all calculations inside `()` at the call site if the symbol is not defined.
Good, because LoggerMessage.Define does what your adapter is doing, but eliminates the object[] allocation. Using an adapter is worse, as you need to much around with DI as well
Also talk about BeginScope :)
Nick! Hi. I just wanted to express some gratitude for your participation and contributions to the community. I find your videos very accessible. I think the content is rich, and that you're a pleasing person to learn from. Your approach seems to give lots of care to integrity. We need that. Thank you for your videos!
Hey Nick, really awesome video. I love seeing your perspective on these sort of things. This video got me thinking about other parts of my code that could potentially be performance pitfalls. I ended up creating some similar benchmarks for the MediatR package. It is actually pretty interesting how much memory allocation is going on when calling handlers! Just as an example, calling the handler with the mediator, vs directly yielded execution time that was 50x slower and created over 1.5 GB of allocation over 30 seconds of iteration. Much like your logging example!
Im using Serilog since 2016, its great to know that im in the right path.
Hey Nick, Just wanted to express gratitude for the videos you put out on various topics. learning so much from you.. Keeping sharing!!! love from India 🇮🇳
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.
Nick is my man! He gives me very strong arguments to tell my collegues why I will delete their log calls :D
Log adapter is an interesting idea. I have two possible additions to this.
1. We can use extension methods instead of separate interface/class. This would give us same functionality, but with better performance.
2. We can dynamically create methods for this class using source code generator, that was introduced in net 5.
I though of it too but then I did the following math: ((4 overload) * (6 log level + 1 "Log" with log level parameter) * + 1 BeginScope) * (6 overload from 1 to 6 parameters) = (4 * (6 + 1) + 1) * = 174 methods to generate. Those methods will be in the intellisense every time you want to log anything. And this only to avoid a new object[] allocation that is probably infinitesimal compared to the execution of the method you are logging, and only in the cases when the log level is not enabled. Considering all the benefits of LoggerMessage.Define, is this worth the trouble?
What about such extensions:
public static void LogInformationPlus(this ILogger logger, Func getMessage)
{
if (logger.IsEnabled(LogLevel.Information))
logger.LogInformation(getMessage());
}
logger.LogInformationPlus(() => "Log it");
And with parameters this way:
logger.LogInformationPlus(() => ("Value = {value}", 5));
@@endmrx The closure will make an allocation I think, although it looks cool.
Great video Nick, I remember reading about this in Andrew Lock's blog with a different solution to solve this problem. To be honest I would like to know what's the reason behind .NET not having this implemented.
Wow Nick! what a great video!! Thanks a lot for sharing the knowledge.
Nice video. It was great that you showed how to profile the app so that we can do it on our own. 👍
Thank you for the video. I've never thought the built-in logger is so inefficient.
Very helpful video. Thanks Nick!
Great video, I haven't thought before about this aspect! Btw. Nick are you going to make a course about async, multithreading, etc.? I know that there are some videos about this topic on your channel, but I think that there may be still a place for a "From zero to hero" way :)
Great video! I would love to see a video about Patch endpoint in API. Always wondered how to implement it in .NET
Great video as always! Nick please try to make something for Centralized Logging using whichever open source tool you prefer (Kibana etc.)
Great video Nick. I could imagine this exact senario happening to a lot of poeple who werent even aware of the hefty cost behind the scenes. Looking forward to more content from you.
Hefty might not be the right word, if you care about a few ns per request, then i don't think c# is the right language..
@@Petoj87 was more referring to the default logger where allocations are still made if you didnt know about the method call still happening even if you changed the logging level.
@@GrimReaper160490 while there is a cost its not hefty is almost not even noticeable, unless you call it many thousand times..
Before watching this video, I never really cared about memory leaks and garbage collection. You changed my mind. Thank you for your video.
Thanks, Nick, I learned so much from this video. For one terrifying moment I thought you might talk about something related to log4shell when I saw the title of the video🤣
This is very important, specially in production!! thank you!
Amazing explanation, even I as a noob feel i got the gist of it
Thanks a ton again, cheers
As always, great videos Nick.
Going further, there is also:
- LoggerMessage.Define method
- LoggerMessageAttribute and corresponding source generator
And with InterpolatedStringHandler, you can get a lot better perf even with string interpolation. I'd love to see a video on that 😀
Awesome video. Thank God for Serilog for making this easier to use.
A great one Nick. Thanks for sharing
Warning: the specific trick used here will not work with AOT (ahead-of-time) compilers (like Unity's IL2CPP) due to them being unable to resolve value types in generic virtual functions. If you need this behavior in an AOT environment, use a concrete Logger class instead of an interface.
In that case you can simply use the if check
Thanks for this video! Very helpful!
Most logging systems aren't really that good, particularly for multithreaded and/or always-on environments. At one company, we had a very robust logging system. We designed it to be able to turn on/off levels and such while the service was running and it output a fair amount of information. One simple thing... being able to load it into Excel or, worst case (if the log was huge) Access or SQL Server in order to filter/query it down was very heavily used. Granted, it was a bit overkill for a typical consumer app, I guess, but that logging system was really, really helpful at times.
I have been a developer fro 25 years - and even before that as hobby on C64 :D - and still I learn something new :) Thank you Nick
Awesome information, thanks for sharing 👍🏻
Dude this is a master class!
Thanks for the video. There's another potential performance-related problem left unattended here when arguments themselves need to be calculated somehow. So if you hide the level check in a wrapping method it doesn't go away. The head-on solution would be to use Func or something like that, but I'm not sure where and when it becomes a viable/worthy option.
the solution would be removing conditionally the debug log with #if DEBUG, so to avoid even the branching code
Thanks for the video. I think there's even another option if you really want to get that performance out, and also maybe improve having to put the if's everywhere, and that's using something like Postsharp to do AOP. The specific use case as well would be more along the lines of doing a kind of method trace logging. I remember when starting my software career, learning about Spring and AspectJ, where we did this kind of pattern in the one aspect, and then could apply tracing anywhere in the solution by just configuring some conventions. Not sure if it would always add the logging code for us, or if there was an option to not weave in the logging code based on a configured log level.
But yeah, if you really want to you could build a solution to weave in all these logging statements with the if checks for a "Debug" build, and then for the "Release" configuration you don't even pay the penalty of the if statement because it's not even there ;) Though, I guess that comes with the downside of not being able to turn on the debugging levels at runtime without doing another release, but if you really have to, its another option I think :)
(Also, just to note, I had a better experience with Java Spring and AspectJ, than with C# and Postsharp, so it's not that I'm recommending it, just mentioning it :B)
Thanks nick! it seems your video answered the issue of memory leak that I face last year. Do you have course for advanced topic like this?
Priceless! 👍🏽
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.
Great info, I learned something new again :). Thanks
As always great video 💪
Thanks! This is great stuff. Also, I kind of like your choice of numbers..
9:40 favorite part. Great video :)
Great video as always!
A lot thanks for showing it.
If you want to get rid of the performance penalty for having the additional method call, it might be doable by just adding the MethodImplAttribute with AgressiveInlining. I'd assume with the generics in the methods the JIT doesn't inline the calls by default so encouraging it to do so, might help (and since it's just an attribute you don't have much to loose putting it over the log methods).
Thanks for sharing that one, nice suggestion. I was thinking along a similar train of thought, considering something like AOP with Postsharp to add in logging code, but then I was also thinking more in terms of something like trace logging, which it most likely wouldn't be a good candidate for in the case of logging parameterized strings anywhere in the codebase.
You also have to call the methods on the concrete class, not the interface. The interface method is virtual and can't be inlined. In any case, when you're writing the adapter yourself that's not a problem.
Edit: I wasn't 100% sure about inlining of the method if called on an interface, but now I've tested it. It won't.
Great video. Thanks!
Thanks Nick 👍
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, great video. Just wondering why you chose to do this using adapters, as opposed to just creating extension methods on ILogger?
Extension methods generally are harder to unit test and the default logger is basically impossible to unit test as it is anyways due to falling internal classes so adapters solve that problem plus the memory one
If you are testing your extension method, you simply have to ensure ILogger.Log method is called when it should and then that all you parameters are taken into account. In this case, mocking Ilogger seems pretty trivial (less than 20 LoC). formatter(state, exception) returns a string. So it is simple to test, whatever the type of TState is.
@@vincentjacquet2927 With the adapter I need 1 line of code. 20 is 19 lines too complicated
Awesome video Nick. The dotMemory part especially. Do you think it's worth its separate video? It's great how you show various approaches to measure the difference in performance. Also on the part of string interpolation. Do you think the new InterpolatedStringHandler from C#10 can make interpolation to be a valid method of logging?
I might make a video on dotMemory at some point. No you should never use string interpolation for logging.
This video was great, thank you so much 👍🏻👍🏻👍🏻👍🏻
I am going to start using these `if`s
Currently, I use extension methods to do logging, so I can add the if to the extension method.
Do you know, if there is any Aspect or Fody that would replace the if statement?
a Higher-order function might work, but the aspect would be neater.
Thank you again for the video.
Not a fan of the Aspect/Fody approach but you can use source generated logging to get around it
"You're gonna be blinded in 3, 2, 1... now!"
You made my day))))
Thanks Nick.
Nick! Hi, What about the conditional attribute on the logging method to avoid the method being called altogether? Any thoughts on this
Dziękujemy.
Great video as always! Do you know if the "Serilog way" applies to other popular libraries such as NLog as well?
I have never used NLog so I wouldn't know
Nlog solves it the same way like Serilog.
"Imagine if in a game server, the server pauses and does nothing" 15:00
It happened - WoWD emulators were notorious for this "world freeze"
Thanks for the content - it's cold.
Also, this GC was the reason Discord changed languages.
Hi Nick, can you make a video about CPU & memory usage debugging in .NET? I would love to learn how to do it, I've developed an app which consumes quite some memory and I am not sure how to check it.
Excelent Video!
Ah, I was expecting your take on the log in process. Like many I'm looking for an effective authentication (plain javascript on front and blazor on backend) - so far I like basic auth (plain base 64 string) with salt over https.
Nick, when using serilog, do you it with ILogger or with their static singleton Log class?
Anyway an episode about ILoggerbor Serilog would be great 🙏
Thanks!
I tend to go with the singleton approach
I think a follow up to how you use serilog would be interesting, as I am a serilog fan
I use compile time conditional statements around debug logging if Im worried about performance
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?
Nick, very interesting choice for your two favorite numbers! 🤣
It must be great to know everything better.
Great video!
Excellent video, thanks Nick. I've taken over looking after an OLD .net 4.6 frame work project that uses Log4net, but in the code I see a lot of log.debug("...") lines withOUT the if statement (or adapter) would you recommend this is also just as bad as your video was all to do with .net core 6 and not 3rd party old loggers.
.NET Framework is generally slower so I would expect it to be worse
The problem shown is a common one, regardless of which runtime you use. Therefore it is clear: you should address this problem.
But with extension methods (I don't share Nick's opinion that extension methods are worse to test) you just need to create those extension methods and most code would use them right away - just make sure they are in the same namespace as the logger interface.
As for performance, I share Nick's guess that the impact would be even greater in the old .NET.
Thank you for the very interesting video, Nick! In a current project I am using the Microsoft.Logging.Abstractions as the adapter, and Serilog as the engine. As I understood you the benefits of Serilog would have no effect here, because the boxing still take place. Am I right? Sould I use the Serilog ILogger interface instead?
Yes you are correct
@@nickchapsas Thank you! Than I have a lot of work ahead of me 😂
@@nickchapsas This is my biggest issue :( Reusable libraries (aka nuget libraries) should be logging-framework agnostic, IMO. Which usually means they pass around an ILogger from Microsft.Logging.Abstractions. And the host application can then determine which logging framework to use: like Serilog! It's like a win-win scenario! But now ... we're getting the boxing/allocations problem :( So it's like MS should needs to update their adaptor to have the IsEnabled there .. and then we'll all be winning! Does this make sense?
@@JustinAdler I don't bother with the logging abstractions. Microsft.Logging.Abstractions isn't the first attempt at creating a logging abstraction for .NET but they always end up being leaky or limited. Performance issues aside, it's a pain to do logging from static methods with the MS logger.
I just use the Serilog singleton in a static field (Log.ForContext....) and avoid the whole mess.
@@nickchapsas If we use the Serilog ILogger interface, do we give up the ability to use BeginScope to add properties to a scope?
start using random number 42 too :-P good video!
Thanks
You can just lower down resolution of your monitor to make everything looks good on video while recording, so you don't have to scale anything.
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.
I think string interpulation works differently now, I’ve seen it turned into numbered templates as well as an object array
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.
Great video as usual! does it make a difference if you put the code inside 'using'
No
What's a good way to track the number of event occurrences in a given timeframe? say i want to have the number of successful logins in the last 24 hours, is there a library that does this sort of stuff or should i build it myself? stuff like AppMetrics don't really have that (there are gauges, but can't select a timeframe eg. last 10 minutes, last 24 hours ect...)
One question I have for Serilog, is that in many samples for dependency injection for Serilog the Microsoft ILogger gets injected. If now the LogInformation Method from that logger is used we get the same problem again. So just inject the Serilog ILogger or use the static Log class?
Inject the Serilog ILogger. Don't use the static class
Hi Nick, should I still be worried about the memory allocation when I'm using log4net in .netcore? great vid btw..
This is just my anecdotal evidence but I had bad memory leak/allocation issues when using log4net in my .net framework WPF application.
Switched to using Serilog and that basically went away completely.
Sorry if this has been asked before but here are way too many comments to find anything in them. If the additional method call outside the if condition causes some extra runtime in the benchmark, I'd suggest adding an attribute to do aggressive inlining to it. Have you considered that? If it's picked up by the compiler, it would increase the compiled code size a bit but should avoid the extra runtime cost, making it compile- and runtime-equivalent to manually coding the if condition, but without the typing work and with the increased readability.
Hi Nick, nice one as always!
One question though: if I use serilog and Microsoft ilogger, what happens? Is the if check already happening because the Microsoft ilogger uses serilog?
No because you have to go through Microsoft to get to Serilog so you’re already affected by the issue at this point
Upvote for double blind Nick Chapsas! Long days in the office? Remember to take care of yourself!
Great stuff Nick. But why is this not already build-in in the .NET Logger Class??? 🧐
Because it would be a breaking change so they couldn’t introduce it without breaking existing code of people using it
You are awesome. I am Nigerian, you have any idea if I can pay with a local bank debit card for any of your courses
Just want to say thank you for being that collage professor i missed out on. Your videos are always enlightening, even if i am knowledge in some of the contents hinted in your titles i feel there is always something to take away when you start breaking the topic down.
When using DI, how do you register the logger adapter? Would it be:
- coped/transient - in this case if it is injected into another scoped one (e.g. a controller), wouldn't it be an overhead itself creating the extra object?
- singleton - will a config change of the log level during runtime will applied in the singleton? (I really don't know about that, I should check how the runtime reload of the config works...)
I would be curious about another benchmark: you would probably want to generate the random numbers outside of logging - because you "want" to use the value for something else - and only the boxing would happen ; how does that would compare for enabled and disabled log levels?)
Actually, why not creating a PR in Microsoft.Logging.Abstractions to handle the boxings cases? Ok I guess that would not be that trivial, for all the dependent implementations...
You are pointing out a very interesting thing here. If you got any answers to the questions related to DI and generating random numbers outside of logging , I'd be happy to hear them.
Great video and topic ,
Q: dose using the serilog but using the Ilogger abstraction is still benefit the Serilog level check ?
Request: a memory leak diagnostic video. With dot net memory or other tool will be a great subject to overview by your side.
No if you’re using Serilog through the Microsoft ILogger you still suffer from the same issue
Well this might explain why I had a really bad memory leak/allocation when using log4net. After I switched to Serilog my memory usage went waaaaay down.
Thanks for the TIP.
Do you think using string interpolation like places in logger can cause OutOfMemory exceptio ?
It really depends if you logging provider is caching the string template in a dictionary. I have seen similar memory issues in the past
@@nickchapsas Thank you. Let me try this approach to see any improvement
as always 👏🏽👏🏽👏🏽👏🏽👏🏽
So it is incorrect to assume that using the Microsoft.Extensions ILogger interface with Serilog as a provider, I don't need to do the IsEnabled check because Serilog will do the check for me? Because the Microsoft provided interface has an object[], it will allocate when called even though under the hood it will later use Serilog to actually log yea?
Just want to add few things:
1. (By default) config will pick both Appsettings and Appsettings.Development configurations. The variables from configuration loaded later shadows variables from “earlier” configurations. It is pretty simple and powerful concept - there is no need to write ALL variables in environment (dev, qa, prod etc) configurations, only these are needed to be changed. Common settings will be picked up from default configuration. It helps to have more simple and concise configurations
2. I’d like to generalize idea of this video to “try to avoid logs in application hot paths in general”. Logs are really expensive, especially console logs (in Windows, at least). I spent lot of time trying to understand why performance is 10x lower than I expected and finally found that console logs were the reason
1. Yeah it's an override mechanism, which in itself can be configured differently btw.
2. You don't need to avoid logs in hot paths. You just need to use their optimized versions. .NET supports the LoggerMessage.Define approach which is a cached delegate that's really efficient and won't box anything and also the source generated version which also uses the LoggerMessage.Define. No one is (should be) doing console logging in production, you would only do batched logging in something like Elasticsearch, Datadog and so on in the background. That's how Serilog sinks work. What you do need to be careful with however is overlogging. I usually won't log anything below a warning in production and if something causes an error or a warning I will retroactively log any information log in that execution so I can see the full story.
GC is not always blocking your application. But good tips Nick
Great video
Nice video!
how do you implement dependency injection of ILogger into DurableTask.Core orchestrations and task activities?
I get the boxing issues, but have you tested the gc in production environments? Does it cause measurable performance degradation because of the gen0 collections?
It does yes
@@nickchapsas I like the idea of using an adapter pattern with generic parameters to prevent unneeded boxing. I'll be updating my telemetry library to take advantage of the generic args as well as perusing Serilig's source. Thanks for the idea. I also appreciate seeing Jetbrains memory tooling in action. I've been wanting to try it out but haven't had the time. I'll be following your channel a bit closer now.
Really really cool, thanks for this Nick!!
Did you consider using overloads for the log functions that take an IFormattable message? You can pass an "interpolated string" to it, but the string is only "rendered" when you ToString it. Even the expressions that are interpolated are only evaluated at that time (hmm this is not the case in my test but there should be I read it somewhere... 🤔).
Yes, if you log the same thing in a loop it will still allocate a string multiple times, but all other problems discussed here should be resolved.
It's not a good solution it's just more overhead
They introduced InterpolatedStringHandler in .NET6. I suppose, there will not be a problem to use string interpolation in logging soon.
That wouldn't fix the fact that you are destroying structured logging by doing that. You should never use string interpolation in logs because you are losing the parameter generated by the log. The log message is a template and needs to have the parameters passed as arguements
@@nickchapsas You can use the InterpolatedStringHandler and the new CallerArgumentExpression (in the Append-Methods of the handler) to access these parameter names respectively expressions.
However, in some cases, the expression would not be as readable in a structured log as a specially defined name. For these cases, you need a new variable.
Nick seems like the kind of person who would really really like Rust
Would you implement this only when app is receiving thousands of req per sec/min, or even for apps that receive say a few hundred requests a day. Off course it is good to have it in place from the start but just checking at what point do you really reap in the benefits of this approach? I would assume you need to run your profiler and do a before/after to really compare right?
I would implement this for any app starting with the adapter solution. In a video coming really soon I would show an alternative approach which I would implement only on high throughput applications
@@nickchapsas 👍 thanks!