@@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!
While I think this is a great topic, it's seems a bit overblown... sure doing a logging in a tight loop might be a bad idea and could get some use from a if... but unless its a tight loop or a extreme performance api I would not do this nano (not even micro) second optimization that would make the readability worse... 99% of applications don't need this and you should be a bit more clear about it.. Add a database/write/read file call and you wouldn't even notice the difference of logging or not logging... There is a saying "micro optimization is the root of all evil" and it is sadly true for a lot of your videos (example the enum video), i wish you be more forthcoming about that this is not needed in most projects and should only be done when all big optimizations are done.. I could do this trick or optimize a db query what would yield the biggest perfomrance impact? Any new programmer could be tricked and apply the optimizations you suggest where they aren't needed at all or where they could actually make other changes that would make a real difference. Sorry if I'm negative here but it rubbs me the wrong way when you say that you should be doing this to save a few ns per request..
He is talking about high performance applications, not some internal management software which will have at most 5 people logged in at the same time. Think of hundreds and thousands of users using your application at the same time - the effect of logging things for each request could be compared to running logging in a loop on a single thread. Or, think about some "real-time" applications, like exchanges or as Nick said himself, video game servers. A few hiccups every minute could really slow down such programs. Also, it's not like his solution makes the code less readable or over-optimized. Adding a simple if doesn't really add much complexity, and Nick even showed how you can benefit from the added if, without making your code less readable, by creating a very simple LoggerAdapter, or using a library such as Serilog.
@@BrokoIis he never said its only high performance, but i would say this is something you only do in extreme cases where every ns matters, but if you're counting ns then i don't think c# is the way to go.. Also this should be about the last thing you optimize as there must be other changes you can make that would yield more performance improvements.. I mean we are talking about ns its not even ms..
@@BrokoIis You shouldn't write Realtime applications in managed languages. And all of his videos are designed for the avarage programmer. I think less than 5% of programmers are only that category of micro optimisation. Just querying a database generates way more data that's needs to be garbage collected anyways later. Furthermore servers mostly log into things like ES so there is even network communication involved. Cleaning up business logic is for that more intresting. Further more code should always be handled in a simple way. Because you or anyone else in 3 years will have no idea what you did there. Maybe not with this logging but some of the other remondations go in that direction.
@@mg00 what a friendly response, while i agree that all developers that have a few years of experience will know this without being told, but this is going to be viewed by those that don't.. If you don't care about new developers thats fine but i do.. What is the harm in being clear upfront instead of using sensational titles...
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.
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");
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.
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!
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.
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.
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.
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.
"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.
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.
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 :)
Real bad memory leaks we had with concurrency EF exceptions which were destructed using Serilog.. 1 log message took 64k lines.. never destruct unknown stuff in logging..
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.
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?
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.
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"
let me try and make it better! if(!logger.isEnabled(LogLevel.Information) logger = null; then every call to logger you have to use the null conditional operator logger?.LogInformation(....); which will resume to If(logger!=null) logger.LogInformation(....) Good times will be had with all! I'm ready for my MVP Microsoft! (PS: I'm joking, don't do this)
Well - that idea is not so bad :D The null check should be faster than calling the IsEnabled-Method. But for all situations, where the enabled log level can change (ASP.NET Core can reload the settings), that would be a realy bad thing
Awesome video, but you doing logging wrong. All ms extenstions bullshit is bullshit and slow. Why? Because it doing wrong. Why? Because it pretend to general solution but actually can handle only stupid web app scenarios where speed is not a factor at all. Effective logging never can be done via virtual call. Period.
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?
If your benchmark is pure logging calls it distorts the impact of logging. In a real world app that actually does work and if the logging is 0.5% performance hit - do we care?
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.
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 ?!
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.
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.
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.
You sad not use string interpolation via _loger.LogInformation( $" xxx {parameter} yyy ") in loggin because string will be allocated every time. Was it fixed in C# 10 and CORE 6.0 ?
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.
What if it's a Trace log? What's if it's an Information Log? Most high perf applications have the lowers log level to warning, and assume that no-news is good news. These directives should be use sparingly and this is a bad usecase example.
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.
The approach is quite nice, but I cannot imagine a real scenario in which is application writting 69 milions of log lines per 5 seconds. How much data would they collect if such log is enabled?
I deal with way more on a daily basis. When you're working with APIs that handle 1-3k requests per second and each request will call 10-20 log methods (including internal ones) then you instantly have 10-60k log calls per second. Only the warning or errors might end up in production in your Kibana, Seq or whatever you're using but your app still suffered all that performance from the logs you didn't end up using. 69m is on the concervative side and it is not per 5 seconds.
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.
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 your going to be blinded in 3, 2, 1 now.... And we're all wincing in pain and have to look away. I actually loughed out oud. Light mode to developers is like garlic to Dracula.
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, 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🤣
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.
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
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.
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!
While I think this is a great topic, it's seems a bit overblown... sure doing a logging in a tight loop might be a bad idea and could get some use from a if... but unless its a tight loop or a extreme performance api I would not do this nano (not even micro) second optimization that would make the readability worse...
99% of applications don't need this and you should be a bit more clear about it..
Add a database/write/read file call and you wouldn't even notice the difference of logging or not logging...
There is a saying "micro optimization is the root of all evil" and it is sadly true for a lot of your videos (example the enum video), i wish you be more forthcoming about that this is not needed in most projects and should only be done when all big optimizations are done..
I could do this trick or optimize a db query what would yield the biggest perfomrance impact?
Any new programmer could be tricked and apply the optimizations you suggest where they aren't needed at all or where they could actually make other changes that would make a real difference.
Sorry if I'm negative here but it rubbs me the wrong way when you say that you should be doing this to save a few ns per request..
Can only 100% agree with this. It's so small benifits for pretty much no gain. 2sec in 52sec gc is nothing. And that application did nothing basically
He is talking about high performance applications, not some internal management software which will have at most 5 people logged in at the same time. Think of hundreds and thousands of users using your application at the same time - the effect of logging things for each request could be compared to running logging in a loop on a single thread. Or, think about some "real-time" applications, like exchanges or as Nick said himself, video game servers. A few hiccups every minute could really slow down such programs.
Also, it's not like his solution makes the code less readable or over-optimized. Adding a simple if doesn't really add much complexity, and Nick even showed how you can benefit from the added if, without making your code less readable, by creating a very simple LoggerAdapter, or using a library such as Serilog.
@@BrokoIis he never said its only high performance, but i would say this is something you only do in extreme cases where every ns matters, but if you're counting ns then i don't think c# is the way to go.. Also this should be about the last thing you optimize as there must be other changes you can make that would yield more performance improvements.. I mean we are talking about ns its not even ms..
@@BrokoIis You shouldn't write Realtime applications in managed languages. And all of his videos are designed for the avarage programmer. I think less than 5% of programmers are only that category of micro optimisation. Just querying a database generates way more data that's needs to be garbage collected anyways later. Furthermore servers mostly log into things like ES so there is even network communication involved. Cleaning up business logic is for that more intresting.
Further more code should always be handled in a simple way. Because you or anyone else in 3 years will have no idea what you did there. Maybe not with this logging but some of the other remondations go in that direction.
@@mg00 what a friendly response, while i agree that all developers that have a few years of experience will know this without being told, but this is going to be viewed by those that don't.. If you don't care about new developers thats fine but i do.. What is the harm in being clear upfront instead of using sensational titles...
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
Log adapter is an interesting idea. I have two possible additions to this.
1. We can use extension methods instead of separate interface/class. This would give us same functionality, but with better performance.
2. We can dynamically create methods for this class using source code generator, that was introduced in net 5.
I though of it too but then I did the following math: ((4 overload) * (6 log level + 1 "Log" with log level parameter) * + 1 BeginScope) * (6 overload from 1 to 6 parameters) = (4 * (6 + 1) + 1) * = 174 methods to generate. Those methods will be in the intellisense every time you want to log anything. And this only to avoid a new object[] allocation that is probably infinitesimal compared to the execution of the method you are logging, and only in the cases when the log level is not enabled. Considering all the benefits of LoggerMessage.Define, is this worth the trouble?
What about such extensions:
public static void LogInformationPlus(this ILogger logger, Func getMessage)
{
if (logger.IsEnabled(LogLevel.Information))
logger.LogInformation(getMessage());
}
logger.LogInformationPlus(() => "Log it");
And with parameters this way:
logger.LogInformationPlus(() => ("Value = {value}", 5));
@@endmrx The closure will make an allocation I think, although it looks cool.
Great video Nick, I remember reading about this in Andrew Lock's blog with a different solution to solve this problem. To be honest I would like to know what's the reason behind .NET not having this implemented.
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 😀
Im using Serilog since 2016, its great to know that im in the right path.
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!
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.
“Let me add two random numbers.. “ - Ohh, let me guess… :)
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 :)
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.
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.
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.
"You're gonna be blinded in 3, 2, 1... now!"
You made my day))))
"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.
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.
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 :)
Real bad memory leaks we had with concurrency EF exceptions which were destructed using Serilog.. 1 log message took 64k lines.. never destruct unknown stuff in logging..
"Lets have a couple random things here...": 69, 420
Me: "yea... totally random" 😂
how do you implement dependency injection of ILogger into DurableTask.Core orchestrations and task activities?
can't be doing it wrong if i don't do it at all
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.
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?
JEZUS..MICROSOFT PROGRAMS LIKE A NOOBS! And this is in their framework!
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.
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"
let me try and make it better!
if(!logger.isEnabled(LogLevel.Information) logger = null;
then every call to logger you have to use the null conditional operator
logger?.LogInformation(....);
which will resume to If(logger!=null) logger.LogInformation(....)
Good times will be had with all!
I'm ready for my MVP Microsoft! (PS: I'm joking, don't do this)
Not gonna lie, my blood pressure was rising as I was reading this
Well - that idea is not so bad :D
The null check should be faster than calling the IsEnabled-Method.
But for all situations, where the enabled log level can change (ASP.NET Core can reload the settings), that would be a realy bad thing
Awesome video, but you doing logging wrong. All ms extenstions bullshit is bullshit and slow. Why? Because it doing wrong. Why? Because it pretend to general solution but actually can handle only stupid web app scenarios where speed is not a factor at all. Effective logging never can be done via virtual call. Period.
Upvote for double blind Nick Chapsas! Long days in the office? Remember to take care of yourself!
That's bad. Really bad. I just don't even remember how to use parameter approach instead of the modern string interpolation. Sad about this.
Why use a random generator when 69 and 420 obviously are absolute randomness?
"Throw in a couple random things..." *uses 69 and 420* "random" indeed. 😆
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?
If your benchmark is pure logging calls it distorts the impact of logging. In a real world app that actually does work and if the logging is 0.5% performance hit - do we care?
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.
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 ?!
I use compile time conditional statements around debug logging if Im worried about performance
Great video! I would love to see a video about Patch endpoint in API. Always wondered how to implement it in .NET
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.
GC is not always blocking your application. But good tips Nick
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.
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
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
Is this still relevant currently? Kinda stupid if ms still havent optimize this in the box
Probably. Lol 😂 I don’t know much of anything about it.
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
You sad not use string interpolation via _loger.LogInformation( $" xxx {parameter} yyy ") in loggin because string will be allocated every time.
Was it fixed in C# 10 and CORE 6.0 ?
I am not doing logging wrong, .NET is doing it wrong. Going back to my log4j :P
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
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..
Why wouldn't you just use precompiler directives ant it would not even be considered to compile? #IF DEBUG then log #ENDIF
What if it's a Trace log? What's if it's an Information Log? Most high perf applications have the lowers log level to warning, and assume that no-news is good news. These directives should be use sparingly and this is a bad usecase example.
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?
"your going to be blinded in 3,2,1 now!" Ha ha ha
The approach is quite nice, but I cannot imagine a real scenario in which is application writting 69 milions of log lines per 5 seconds. How much data would they collect if such log is enabled?
I deal with way more on a daily basis. When you're working with APIs that handle 1-3k requests per second and each request will call 10-20 log methods (including internal ones) then you instantly have 10-60k log calls per second. Only the warning or errors might end up in production in your Kibana, Seq or whatever you're using but your app still suffered all that performance from the logs you didn't end up using. 69m is on the concervative side and it is not per 5 seconds.
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
Is there an open issue for this in there github ?
Ah yes randoms numbers 69 and 420 ;-)
Can someone please tell me why he changed int to var at 11:46 Thanks
Does Nlog also implement this like Serilog?
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
And your going to be blinded in 3, 2, 1 now.... And we're all wincing in pain and have to look away. I actually loughed out oud. Light mode to developers is like garlic to Dracula.
I always learn something new, thanks Nick!
LOL the vars….up and down…I can’t unsee 69 & 420 and resort to 10 yo humor
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...)
Am I the only one that heard Chewbacca at 09:33?
11:11 - "Which is probably the first time we're using an actual random number" 😂
Great video. Thanks!
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.
Thanks! This is great stuff. Also, I kind of like your choice of numbers..
What an arrogant title
You clicked
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.
I think string interpulation works differently now, I’ve seen it turned into numbered templates as well as an object array
I heard Java is doing their logging pretty well ;)
Yes but the interface is really bad
Log4Net has the same security problems as Log4j?
No as far as i know it does not have
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!
This is very important, specially in production!! thank you!
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🤣
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 ^^
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
Very helpful video. Thanks Nick!
πέθανα με το 69, 420
Nick, very interesting choice for your two favorite numbers! 🤣
I'm not doing .NET logging at all!
as for me you are struggling hard with tiny problem
To me this is one of the really big problems I am dealing with. It is VERY visible in the apps I work on
Nick seems like the kind of person who would really really like Rust
i don't do logging hahahaha
Great info, I learned something new again :). Thanks
Very interesting... :)
Thank you for the video. I've never thought the built-in logger is so inefficient.
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.
I think a follow up to how you use serilog would be interesting, as I am a serilog fan
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
Thanks for this video! Very helpful!
Amazing explanation, even I as a noob feel i got the gist of it
Thanks a ton again, cheers
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
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