High-performance logging in .NET, the proper way

hello everybody i'm nick and in the previous video i explained why you are most likely are doing logging.net wrong in this video i'm going to show you how you can do high performance logging in.net and optimize what we saw on that video even further but because you need to understand what's wrong with logging in the first place i highly recommend you check that video first we're going to put it on the top right corner on your screen right now click that watch that and then come back in this one to have the full picture because i can't just recap 25 minutes of video in one minute i'm gonna try but i don't think i i can do justice to all that other content so please check that first then come back here and see how you can optimize your logging to effectively perfection with the tools we have today if you like type of content and you want to see more make sure you subscribe earning this notification bell and for more training check out nickchapsas.com this video is uploaded on the third anniversary of this youtube channel and to thank you all for being here and helping me grow this channel from nothing to what it is today i'd like to give the first 100 of you a 10 discount code on my already 15 discounted cost bundle and this includes both my dependency injection cost and my unit testing course there's tons of value here with both courses being from zero to hero meaning from the very basic to the very advanced stuff so if these two topics are of interest you use this discount code that you see right now for 10 off so let's see what i have here and i changed the code from that old video a bit but let me just explain quickly what's the problem so we have this log debug call here which we're logging how many days we're retrieving the forecast for the weather for if i quickly just run this to show you what this looks like in action and if i increase that a bit when i go here and i call that end point with three days as a query string parameter it will log that hey this uh method over here log retrieving weather forecast for three days and that's it now the problem is that when i'm running this in production this debug log will be ignored because in production my minimum log level is information however in development it is debug and this can be any combination you might want to have warning in production and information in development and so on so don't really focus too much on the fact that it is a debug log it can be any log level um the problem with that is that this line will be called in production even if the log message will be eventually ignored to get around that the quick solution is to have an if check that says that if the logger is enabled for that log level then step into that and it will only go in here if the application will actually do something with those debug logs and this will fix the problem where the log level is lower than the accepted log level and you won't allocate extra memory and the reason why this is a problem by the way is because if we go to the log debug call you see that we have these parameters object array for the arguments the problem with that is that first you're going to have to allocate an array which is a reference type going on the heap and it's expensive because we're going to allocate memory and this memory will need to be gaps collected but also if you have a value type like we have here the days is an integer which is a value type this value type needs to be boxed to be allocated as an object in that array and this is extra allocations so we don't want to do that and for that reason we have this each check however if the log level is matching that level like this one then we have this if check and we will eventually box this parameter because we need to because we need to log how do we optimize this well this is what this video is all about so i want to go here in this benchmarks project i'm going to show you what i have here i have a few benchmarks and the first one is using the log information with a couple of parameters and this log message over here to see how much memory and how long it takes then we have the same thing but with an if check and then we have a logger adapter which is wrapping the eye logger that you can see right here so i'm injecting it and then i'm wrapping it and with this call and then i have an if check so if the logger is enabled for that information then i'm actually calling that method optimizing even further and what i want to do is i'm going to go ahead and show you here they have a log level warning here but all these logs are information logs so i'm going gonna run these benchmarks in release mode and see how they perform and then explain why even though this fixes one of the problems there is still a problem that we haven't fixed yet so let's wait for the results back and show you what the actual problem behind the scenes is so results are back and let's see what we have so like expected the first one is allocating 88 bytes and by the way if you think this is low again check my previous video it shows what real world impact this 88 bytes or how many there are um can have to your gabby's collection because that's really what's hurting you then this is taking 63 nanoseconds and then the one with the if check is taking four and the one with the adapter is taking eight ish nine ish so it fixes the problem in a more elegant way a bit slower than the straight if check because you have those generics and that method call but it's still way more efficient than the raw version now here's the thing this is all about when the log level is lower than the accepted one the minimum one but what if the minimum one is information right what happens when you do need to log those messages well i'm going to update that to information and what i've done is i've added a fake logger that i wrote which effectively does nothing with the logs and the reason why this is here is to show you what happens when you are logging into a specific uh will sync or let's say console file system elastic sets whatever in a very narrow down way an isolated way because if i don't add a logger implementation then the log is being ignored completely so i created a fake one just to show you what's happening so let's go ahead and run those benchmarks again and see what we get back this time so now the results are back and let's see what we have so you can see that now all of them actually allocated eight eight bytes because eventually those value types got boxed for the execution and the previously efficient approach is actually slower because you have the generics and the eav check this one here is a bit more efficient and the raw one performs the best speed wise and they all allocate memory again this doesn't show the performance gain of not calling the log level being lower than the minimum but when you need to log them then all of them will use the same amount of memory so this is what we're going to go and optimize now so there's actually two ways to optimize for high performance logging that will fix that problem the first one i want to look at is the logger message definition so what you can do is let me go ahead and create a new class and call it logger message definitions here i'm going to create this class and this will be a static class and in here we're going to create a private static read-only action that accepts ni logger and then in that benchmark we have two parameters two integers so for that reason i'm gonna say int and int those represent the parameters i'm going to accept in my log message and then i need an exception that is nullable at the end this is because what we're going to use requires it and then this is the what can we call this this is just the log message definition that's a very generic name i don't want to call that message definition realistically you would give it a name that represents what you are logging for so let's just call it benchmark log message definition and that would be now a logger message dot define and we're gonna need the two parameters that we have into one and into here so that's what those generics represent and first we need to have let's go here at the log level in my case that will be information for the benchmarks then we can have an event id which is extract with an implicit operator it is effectively an integer that allows you to identify a set of logs by giving them a number so let's say all weather retrievals are 1001 or customer related or like all customer was updated or customer was created is 2001 and so on i'm gonna use zero because the default one is using zero and you can even use the named approach to give it a name and say for example that this is benchmark i don't need that so i'm just gonna say zero here then i'm gonna use my format string which is the the message template for my log so i want this to be the same as the one here so i'm gonna just paste that and that's it we have now the log message definition and i'm gonna go and create a public static void called log benchmark message and this will extend the i logger and will accept the first value and end the second value which is what that other message is also doing and all i need to do is invoke that delegate this action so logger first second and then the exception will be null because i don't actually have an exception here and what that will do now is it will allow me to have a method called like this where i'm saying that logger message definition without if with parameters can be called like this i can say logger dot and this is added as an extension so log benchmark message and then the first number is this one the second number is this one and now let's go ahead and run the benchmarks again and remember these are now effectively logging somewhere i'm doing nothing with those logs but this is what your application would do if you were to log to the level matching your minimum level so let's go ahead and run that again in release mode and see what performance we get back so results are back and as you can see now we allocated with this new method no memory at all because we didn't actually end up boxing any arguments they were passed to that delegate which was cached and it is less than half the time of any other of the methods because remember this is very important you need to have this delegate this action cached and we're doing that by using a static field here and then we're just making an extension method to invoke that you don't really need the extension method but it just makes it more convenient for us and now this is the most efficient way you can go about this or is it because it's actually an extra new way added in.net which is source generating your log messages so i can go here and i can say public static partial class and i'm gonna just use the same name another gen in the end realistically source generated methods classes and all that don't need to have the gen part i'm just adding it to differentiate it from this approach on the top so now i have this partial static class and i can make a public static partial void or this is a method and i can call that log a benchmark message gen and this will again be an extension method on the i logger same thing as i have a above and i'm going to have the exact same signature actually and that's it i'm going to leave it as it is and as you can see this is complaining because it doesn't have an implementation and it needs one to do that i'm going to use the logger message attribute and this is where i'm going to specify first the event id in my case it's 0 then i'm gonna specify the level in this case it is information and then i'm gonna specify the message and in that case it will be well this one so let's go ahead and newline this so you can see it and save and the red squiggly lines went away now i can go ahead and use this method and i'm going to go into the benchmarks i'm going to add one for my source generated log message so i'm going to say logger message source gen here we go that's just an underscore to differentiate that and this is the source generated one so it's that one and by the way before i run this i need to show you that now we have this new behind the scenes source generated class or method and if i click on that you can see that it is actually using the same logger message.define call it is doing that because this is the most efficient way to do it and it is creating an extension method exactly as we did in our case it is also adding the is enabled check and we're going to talk about that in a second but know that automatically tries to optimize even further that's really really cool so we're gonna go ahead and run that benchmark with this source generated version and see how it performs and i know the name says without if because it doesn't have a nif here but internally it does have a knife so take that with a grain of salt so results are back and let's see what we have here so as you can see the source generated version is as efficient as the message definition one that's because effectively they're doing the exact same thing but one we didn't have to write c sharp wrote it for us however in both cases you can actually optimize it a bit further if i go into the source generated one here there is actually a parameter called skip enable check and if i say true because i know that this is for example a warning or it is an error or something that always will be locked no matter what then by enabling that i'm allowing the source generator as you can see here to remove that if check because i know i don't need to waste time making that if check and then let's just run the benchmark to see how that compares against the other one which by the way and you should probably know that um if you go into here and you add this options object you can also skip that check in that delegated version with the with the action but just to see how they compare against each other i'm going to remove that and i'm going to go ahead and run that benchmark for one final time and see what we get so for one last time results are back and as you can see by removing that if check we optimize speed even further again no memory was allocated either of those approaches are the best way to go about it however be careful with that if check because if it is a lower log level then you optimize if you don't log it so if you do have that effect play around with the toggles try it yourself again you can find all the code in the description down below and see how you can optimize your own logging even further well that's all i have for you for this video thank you very much for watching special thanks to my patreons for making videos possible if you want to support me as well you're going to find the link in the description down below leave a like if you like this video subscribe for more content like this ring the bell as well and i'll see you in the next video keep coding you

Channel: Nick Chapsas

Views: 71,830

Keywords: Elfocrash, elfo, coding, .netcore, dot net, core, C#, how to code, tutorial, development, software engineering, microsoft, microsoft mvp, .net core, nick chapsas, chapsas, clean code, dotnet, logging, logging in C#, logging in .NET, you are doing logging wrong, serilog, better c# logging, better .net logging, elasticsearch logs, kibana, high-performance logging, high performant logging, log performant, appmetrics

Id: a26zu-pyEyg

Length: 15min 55sec (955 seconds)

Published: Thu Jan 13 2022