@@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");
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.
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!
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.
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.
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.
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.
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 🇮🇳
"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.
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.
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
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.
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.
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🤣
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.
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?
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.
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.
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.
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.
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.
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.
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!
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.
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.
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)
One problem with your demonstration here, you don't account for optimization. If you build a for-loop that only has if false in it, it will simply get optimized away, this is why you some things like 100000 faster execution with the if. This is a situation that is almost impossible to encounter since when would you log a variable that is created in the logger call. To fix this assign the variable before you do the check for the log level, this would simulate your original case from the Controller. But other than that a very good video, was very surprised moving from Serilog to Log4net that this was not implemented. Good usage of dotTrace as well.
Such an if check as shown in the video won’t be optimised away because it’s a runtime check. BenchmarkDotnet runs the jitted code. If false will only get optimised if it’s a compile time if false
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.
Wandering why microsoft didn't place generic overloads right in ILogger. "Six parameters is enough for all! If you want more use unoptimised LogInfoWeird with params array"
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.
Can you make a video like "evolution of how to declare a property"? I would like to show my colleagues all the ways they have available to declare a property.
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?
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.
he marks there is memory allocate when the call is without if logging -> it is better to use with if got that it got the highest speed but I dont really get the point of writing the adapter ^^
False. First, C# is a very performant language, but besides that, knowing goes to optimise your usage of a language has nothing to do with how it compares to other languages
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.
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.
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.
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 😀
Before watching this video, I never really cared about memory leaks and garbage collection. You changed my mind. Thank you for your video.
Thank you for the video. I've never thought the built-in logger is so inefficient.
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.
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!
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
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
Nick is my man! He gives me very strong arguments to tell my collegues why I will delete their log calls :D
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.
Amazing explanation, even I as a noob feel i got the gist of it
Thanks a ton again, cheers
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..
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 🇮🇳
This is very important, specially in production!! thank you!
Very helpful video. Thanks Nick!
Upvote for double blind Nick Chapsas! Long days in the office? Remember to take care of yourself!
"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.
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.
9:40 favorite part. Great video :)
As always, great videos Nick.
GC is not always blocking your application. But good tips Nick
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
Great video! I would love to see a video about Patch endpoint in API. Always wondered how to implement it in .NET
Nice video. It was great that you showed how to profile the app so that we can do it on our own. 👍
Dude this is a master class!
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
great video Nick!
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.
A great one Nick. Thanks for sharing
"You're gonna be blinded in 3, 2, 1... now!"
You made my day))))
Thanks! This is great stuff. Also, I kind of like your choice of numbers..
Awesome video. Thank God for Serilog for making this easier to use.
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.
Thanks for this video! Very helpful!
Nick seems like the kind of person who would really really like Rust
Great video as always!
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🤣
Thanks Nick 👍
Awesome information, thanks for sharing 👍🏻
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.
Thanks Nick.
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
Great video. Thanks!
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
Wow Nick! what a great video!! Thanks a lot for sharing the knowledge.
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.
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.
It must be great to know everything better.
Excelent Video!
Great info, I learned something new again :). Thanks
A lot thanks for showing 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.
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.
Nick, very interesting choice for your two favorite numbers! 🤣
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.
“Let me add two random numbers.. “ - Ohh, let me guess… :)
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
I think a follow up to how you use serilog would be interesting, as I am a serilog fan
Dziękujemy.
I think string interpulation works differently now, I’ve seen it turned into numbered templates as well as an object array
Priceless! 👍🏽
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 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?
Great video as always! Nick please try to make something for Centralized Logging using whichever open source tool you prefer (Kibana etc.)
start using random number 42 too :-P good video!
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.
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 :)
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
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.
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.
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)
As always great video 💪
Thanks
11:11 - "Which is probably the first time we're using an actual random number" 😂
One problem with your demonstration here, you don't account for optimization.
If you build a for-loop that only has if false in it, it will simply get optimized away, this is why you some things like 100000 faster execution with the if.
This is a situation that is almost impossible to encounter since when would you log a variable that is created in the logger call.
To fix this assign the variable before you do the check for the log level, this would simulate your original case from the Controller.
But other than that a very good video, was very surprised moving from Serilog to Log4net that this was not implemented.
Good usage of dotTrace as well.
Such an if check as shown in the video won’t be optimised away because it’s a runtime check. BenchmarkDotnet runs the jitted code. If false will only get optimised if it’s a compile time if false
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
Really really cool, thanks for this Nick!!
Wandering why microsoft didn't place generic overloads right in ILogger. "Six parameters is enough for all! If you want more use unoptimised LogInfoWeird with params array"
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
Can you make a video like "evolution of how to declare a property"?
I would like to show my colleagues all the ways they have available to declare a property.
That’s actually a very good idea. I will make this video this month. Thanks!
@@nickchapsas Thank you ^^
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?
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
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.
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
Great video
out of infinte possibilities of numbers in the spectrum he chooses 69 and 420, you got my respect @NickChapsas
he marks there is memory allocate when the call is without if logging -> it is better to use with if got that it got the highest speed but I dont really get the point of writing the adapter ^^
The adapter adds the generics which prevent the boxing on the call and allow you to have the if check in there without the allocation
as always 👏🏽👏🏽👏🏽👏🏽👏🏽
If you need to worry about the kind of performance demonstrated with the benchmarking, then you shouldn't be using C#
False. First, C# is a very performant language, but besides that, knowing goes to optimise your usage of a language has nothing to do with how it compares to other languages
interesting, thank you. And yes, I didnt use it well 🙂
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.
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
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
This checks should be done via source generation!
Source generators can't edit existing code
I am not doing logging wrong, .NET is doing it wrong. Going back to my log4j :P