@@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
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!
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");
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!
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.
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.
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.
@@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.
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.
"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.
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.
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.
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 🇮🇳
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?
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.
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.
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.
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.
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.
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?
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.
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.
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.
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 :)
Thanks! I think I'm gonna start a separate series of courses that are a but smaller and focus on a single topic, like async or multithreading and might make them part of a subscription. I'm still working on the pricing and the plan, but more things are coming in 2022.
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🤣
1:25 why is {Days} in the message a capital "D" and but your other variables is days (lower case) ? Seems no relationship, other than there being 1 parameter in the string and 1 argument supplied ?!
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.
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?
@@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.
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.
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!
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?
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.
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.
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.
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.
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?
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)
Great video Nick. Question - could you just do this with extension methods instead of a whole new class? Something like: public static class LoggerExtensions { public static void LogInformation(this Logger logger, string message) { ILogger iLogger = logger as ILogger; if (iLogger is not null && iLogger.IsEnabled(LogLevel.Information)) logger.Log(LogLevel.Information, message); } // Other extension methods with T0, T1, etc. parameters } Do you see anything wrong with that? Might be an easier way to update existing applications.
@@nickchapsas ILogger is testable with Mock... in your unit tests you just mock it and then verify the "Log" method since that is ultimately what is being called (and yes we created reusable extension methods to make the verify calls easy). And with the above extension methods, all of our mock logs and verify methods would continue to work as-is.
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.
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.
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...)
I haven't touched .NET 6 yet, but I know going from 3.1 -> 6 they added LoggerMessageAttribute. Would be curious how that could affect some of these benchmarks.
Yeap, source generated logging is one approach. The other one is the LoggerMessage.Define. I will be talking about both of them in a future video. This video was meant to show how you can solve the problem without fundamentally changing your logging approach
You totally missed the point. It is 100% about logging. String interpolation only gets a minor mention. You shouldn’t be using it in logging anyway. It is about the MS logging method boxing value types and allocating parameters
And just to make everything more confusing... If you use Serilog, you'll want to assign the default Microsoft logger to Serilog in startup, and still inject the default Microsoft logger, which during runtime would actually be the Serilog implementation, right? But if the arguments are passed as params, then wouldn't that still cause the heap allocation issue? So the question is -- should you actually instead be injecting the actual Serilog ILogger? Because that's not the recommended implementation AFAIK.
@@nickchapsas Wait really? Thanks for clarifying! That's like... all the solutions I've worked on lol. So I guess the appropriate thing to do is to inject the Serilog ILogger implementation in your services?
It seems you are really missing out on a key feature here, the System.Diagnostics.Conditional attribute. You won't need to pepper your code with the boiler plate if statements, and you can completely remove the logging cost from your release build, as the log function will not actually be included in the build, but will syntactically still work as if it were there. It is as simple as: [System.Diagnostics.Conditional("DEBUG")] internal static void Log(params object[] list){ /*logging code here...*/ } Then it won't really matter if you are using string interpolation or whatever, because everything you do in those arguments will only happen when you are debugging.
Right, and how do I do that for Trace logs or Information logs during runtime with my application having different minimum log levels depending on the environment they are deployed at? Compile time conditionals are terrible for this usecase. There are better ways to do this that are coming on Thursday's video.
@@nickchapsas I hope you have a "have your cake and eat it too" strategy for your next video. Those if statements are ugly. At times like these I miss C++ preprocessor macros.
@@rickvelde7967 In production environments you don't want to predefine log levels at build time. You want them in your code all the time. So you can switch (parts of it) on in production while an error is still present. At least on code that runs on servers. With client apps running on users own systems this is generally less of a concern.
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?
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?
@@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.
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!
Im using Serilog since 2016, its great to know that im in the right path.
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.
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!
Dziękujemy.
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 😀
Thanks
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.
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
Before watching this video, I never really cared about memory leaks and garbage collection. You changed my mind. Thank you for your video.
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..
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.
"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.
Nick is my man! He gives me very strong arguments to tell my collegues why I will delete their log calls :D
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.
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
Thank you for the video. I've never thought the built-in logger is so inefficient.
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 🇮🇳
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
"You're gonna be blinded in 3, 2, 1... now!"
You made my day))))
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.
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.
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
Amazing explanation, even I as a noob feel i got the gist of it
Thanks a ton again, cheers
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.
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
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.
Great video! I would love to see a video about Patch endpoint in API. Always wondered how to implement it in .NET
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?
I use compile time conditional statements around debug logging if Im worried about performance
This is very important, specially in production!! thank you!
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.
9:40 favorite part. Great video :)
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.
Nice video. It was great that you showed how to profile the app so that we can do it on our own. 👍
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.
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 :)
Thanks! I think I'm gonna start a separate series of courses that are a but smaller and focus on a single topic, like async or multithreading and might make them part of a subscription. I'm still working on the pricing and the plan, but more things are coming in 2022.
It sounds like an amazing opportunity to extend knowledge. I can't wait for it :)
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🤣
1:25 why is {Days} in the message a capital "D" and but your other variables is days (lower case) ? Seems no relationship, other than there being 1 parameter in the string and 1 argument supplied ?!
As always, great videos Nick.
how do you implement dependency injection of ILogger into DurableTask.Core orchestrations and task activities?
Very helpful video. Thanks Nick!
Upvote for double blind Nick Chapsas! Long days in the office? Remember to take care of yourself!
Dude this is a master class!
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.
It's the build in Microsoft one
Awesome video. Thank God for Serilog for making this easier to use.
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
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?
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
Thanks! This is great stuff. Also, I kind of like your choice of numbers..
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
Wow Nick! what a great video!! Thanks a lot for sharing the knowledge.
I think string interpulation works differently now, I’ve seen it turned into numbered templates as well as an object array
A great one Nick. Thanks for sharing
great video Nick!
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.
11:11 - "Which is probably the first time we're using an actual random number" 😂
Thanks for this video! Very helpful!
Great video as always! Nick please try to make something for Centralized Logging using whichever open source tool you prefer (Kibana etc.)
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.
Can someone please tell me why he changed int to var at 11:46 Thanks
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
Great video as always!
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 Nick 👍
GC is not always blocking your application. But good tips Nick
Awesome information, thanks for sharing 👍🏻
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?
I think a follow up to how you use serilog would be interesting, as I am a serilog fan
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?
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.
Great info, I learned something new again :). 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.
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)
Nick, very interesting choice for your two favorite numbers! 🤣
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.
Great video Nick. Question - could you just do this with extension methods instead of a whole new class? Something like:
public static class LoggerExtensions
{
public static void LogInformation(this Logger logger, string message)
{
ILogger iLogger = logger as ILogger;
if (iLogger is not null && iLogger.IsEnabled(LogLevel.Information))
logger.Log(LogLevel.Information, message);
}
// Other extension methods with T0, T1, etc. parameters
}
Do you see anything wrong with that? Might be an easier way to update existing applications.
I don't like extension methods for this because the ILogger isn't really testable to begin with so it solves two problems
@@nickchapsas ILogger is testable with Mock... in your unit tests you just mock it and then verify the "Log" method since that is ultimately what is being called (and yes we created reusable extension methods to make the verify calls easy). And with the above extension methods, all of our mock logs and verify methods would continue to work as-is.
Some of the Log method overloads use internal objects which you don’t have access to mock
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.
Why did the Serilog not have any memory allocations? I thought you said string interpolation gets a memory allocation because it isn't a template.
Serilog is using generics in its methods which prevent the original array allocation unless you want to actually log.
What's the selecty / highlighty thing you're using?
It’s called ZoomIt
@@nickchapsas Thank you
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.
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...)
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
I haven't touched .NET 6 yet, but I know going from 3.1 -> 6 they added LoggerMessageAttribute. Would be curious how that could affect some of these benchmarks.
Yeap, source generated logging is one approach. The other one is the LoggerMessage.Define. I will be talking about both of them in a future video. This video was meant to show how you can solve the problem without fundamentally changing your logging approach
Nick seems like the kind of person who would really really like Rust
It's not about logging AT ALL, but saving a few bytes while using string interpolation. If you use it at all.
You totally missed the point. It is 100% about logging. String interpolation only gets a minor mention. You shouldn’t be using it in logging anyway. It is about the MS logging method boxing value types and allocating parameters
Do you know if the time measured in the benchmark is including the time used for garbage collection?
It’s measured separately
@@nickchapsas How do you include that or show it in the result? I can't find any documentation on that
Great video. Thanks!
Priceless! 👍🏽
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
Would a nullable logger be faster? Something like _logger.Debug?.Log("Hello {Name}", name), for instance
This is bad software design
@@nickchapsas Sure it is. The question is whether it is faster or not
And just to make everything more confusing... If you use Serilog, you'll want to assign the default Microsoft logger to Serilog in startup, and still inject the default Microsoft logger, which during runtime would actually be the Serilog implementation, right?
But if the arguments are passed as params, then wouldn't that still cause the heap allocation issue? So the question is -- should you actually instead be injecting the actual Serilog ILogger? Because that's not the recommended implementation AFAIK.
Using Serilog through the Microsoft logger will have the issue demoed in the video
@@nickchapsas Wait really? Thanks for clarifying! That's like... all the solutions I've worked on lol. So I guess the appropriate thing to do is to inject the Serilog ILogger implementation in your services?
It seems you are really missing out on a key feature here, the System.Diagnostics.Conditional attribute. You won't need to pepper your code with the boiler plate if statements, and you can completely remove the logging cost from your release build, as the log function will not actually be included in the build, but will syntactically still work as if it were there. It is as simple as: [System.Diagnostics.Conditional("DEBUG")]
internal static void Log(params object[] list){ /*logging code here...*/ }
Then it won't really matter if you are using string interpolation or whatever, because everything you do in those arguments will only happen when you are debugging.
Right, and how do I do that for Trace logs or Information logs during runtime with my application having different minimum log levels depending on the environment they are deployed at? Compile time conditionals are terrible for this usecase. There are better ways to do this that are coming on Thursday's video.
@@nickchapsas I hope you have a "have your cake and eat it too" strategy for your next video. Those if statements are ugly. At times like these I miss C++ preprocessor macros.
@@rickvelde7967 I do
@@rickvelde7967 In production environments you don't want to predefine log levels at build time. You want them in your code all the time. So you can switch (parts of it) on in production while an error is still present. At least on code that runs on servers. With client apps running on users own systems this is generally less of a concern.
Nick! Hi, What about the conditional attribute on the logging method to avoid the method being called altogether? Any thoughts on this
Is there an open issue for this in there github ?
As always great video 💪
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
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.
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.