You are doing .NET logging wrong. Let's fix it

hello everybody i'm in this video i'm going to talk to you about logging in.net and why you are probably are doing it wrong now this video has to do with performance and like anything performance related you have to put everything you see here in the context of your use case it doesn't mean that just because i'm talking numbers and allocations and everything you have to go with the most extreme solution right out of the get-go you have to be pragmatic with your choice and choose which one you want to go with but you will also know how to optimize when you need to so that's what this is about you don't have to worry about prematurely optimizing your code but you will know how you can because logging actually if done wrong and most likely it is done wrong can really cost you some performance if you like a lot of content and you want to see more make sure you subscribe earning the certification bell and for more content check out nickchapsters.com and talking about nickchapters.com i just bundled up both my courses for a discounted price as part of my essentials bundle so i highly recommend you check that out in the link in the description so what do i have here well let's start with this basic web api because i want to explain the problem here so i have this controller here this were the forecast controller and i've only changed it a little bit i'm accepting a days parameter over here which by default is five and then i am logging in in a debug log that i'm retrieving the weather for an amount of days the days is a parameter over here and then i'm using that to retrieve the weather and if i was to run that let's see how that looks like from an api perspective so i would call that with a days of three and i'm getting three days back pretty straightforward now as you can see down here i am logging that in debug mode however debug mode by default isn't enabled in asp.net core actually the default is information you can change that in the app settings file and if you see here in this appsettings.development.json file this is where i'm changing it i'm changing the default log level to debug these log levels mean that you will only log in a given medium in this case it's the console but it can be the file system it can be elastic search it can be tons of things but it means that anything below that threshold will not be actually logged and everything above it will so if this was for example information which is a level higher then the debug log would not actually appear in the console and we're going to see that in a second let me just revert that back so we have that debug here and this app settings.development.json is driven by the asp.net core environment variable and you can see that in the launch settings in here i have this loggingbestpractices.api.dev which is what i just run up here and as you can see i'm using the development asp.net core environment and that's how this is loaded anything that doesn't have a specific environment suffixed app settings file will default to this app settings.json so in our case this production one will actually use this app settings.json and in this one because it's production and we don't want to overload because overlogging actually is bad and we upped the at the default log level to information instead and in that case if i go ahead and i run that over here you will see that when i call that endpoint now we're not actually logging anything in here because that is a debug log and it's totally being ignored however this is where the trap actually lies we still actually call that method and this is bad because the log debug or any log extension method on the i logger which is the default one is using the parameters object array why is this bad well an object array means that value types need to be boxed to be put in that array plus it's an array meaning that this will be allocated on the heap let me show that actually in action if i go back to actually let's keep that to prod and and do a debug here since this is prod this debug log will not actually be output anywhere will be completely ignored however when i call this endpoint this method will be called and that's bad because if i go over here and i load memory and then i step over it obviously there is nothing in my console because the debug log is lower than information so it's ignored but if i go back to memory and i reload you can still we have obviously the string allocation of the log but we also have one new object array over here and we also have an in 32 down here and the in 32 you can bet money that it is the three that we just allocated which is one of these two and the array and i'm not going to search all the one item arrays over here but one of these arrays contain um a three i'm not going to open every single one of them but you can trust me that three is there and that's bad because even though the console logger behind the scenes will check whether that's enabled and not actually log in the console you still waste memory on allocating both the array and also boxing the value even though it's not used so the simple solution to this is that you can say if logger dot is enabled and then you provide a log level so you say log level dot debug so if that's enabled then you log it now this looks a bit clunky doesn't it because that means that every time you have a log message you have technically to have this over here but as you can see now if i rerun this and i go back to the memory diagnoser and i call that endpoint and we've hit that breakpoint if i load memory again we have that but then i step over that call and we didn't even attach this line and then when i load again none of anything in here was allocated any allocations were done in that call necessary to make sure that this isn't called so you can see here that no ind 32 was actually allocated now because this is a bit abstract i want to put that into perspective and run some benchmarks to see what it really means in terms of performance so i have a benchmarks project here let me just close everything but that and i have pre-allocated a constant string here and a log message this one has parameters this one doesn't and i'm using the i logger factory which behind the scenes is used to create a logger and i'm creating a logger here it's a read-only one reused for every test so let's say that we have a benchmark here which is a public void log without if so this is your default logging approach so it is logger dot information and because this is warning the actual output of this method will be ignored so we don't really care about how this performs when you're actually logging something because that logging needs to happen that's fine but when you don't need to log something because the log level is higher but you're still calling that method what's the impact on that so here i'm just going to have first the log message that doesn't have any parameters and then i'm going to have the alternative that has an if so with if so if logger is enabled and obviously this will be false because well this is warning so it will be ignored but let's run a benchmark with these two and change that to release and select the right one and if i run that benchmark let's see what's the difference between something that calls the method but obviously the output isn't used and something that calls the method only when the log level is enabled so results are back and let's see what we have here so the with f takes three nanoseconds and the without if takes 14 nanoseconds now what i forgot to do is slap a memory diagnoser here and this will let us know how much memory is actually allocated in these two use cases let's go ahead and rerun this and see what the memory looks like now we don't have any parameters here that need to be allocated so we'd expect the memory to be zero for both but this will become a bit more interesting when we add the parameters into perspective so let's wait for this to finish and then talk about how that affects performance so results are back and let's see what we have so like i said no memory allocated for neither of those that's because we don't actually allocate anything the string here is pre-allocated in this const so we're fine however what happens when i duplicate that and i bring log without f with params so with parameters so this is the log message with parameters and i can have a couple of or a few actually how many do i have here one two uh let's delete one of those why not so let's have a couple of random things over here here we go and then let's duplicate that over here and then i'm gonna slap that name here and now with the parameters which will be formatted into the the log message let's see how allocations mostly is affected so let's give that a go and see how it goes so results are back and as you can see um the first values are the same but the second one we have 88 bytes allocated here which is these value types being boxed in the array but the one with the if doesn't have any of that memory problem because the code doesn't even step in here now i would expect this and this to perform the same because effectively they are the same thing but to my surprise as well this one took longer now that being said when i was preparing for this video it was way closer so i don't know what happened there maybe a fluke with an underperforming call running the test i don't know but the main point is the memory because that's really what's gonna really affect your performance because more memory you allocate the more garbage collection you have to do and when something's being gone is collected your application is just paused doing nothing and it's that time which the users will actually experience now you might be looking at this and be like okay 88 bytes big deal but let's actually take a look at what this really means in the context of your application running so what i have here is a console application that will just log a random number um which is probably the first time i'm using an actual random number but it's gonna load a random number um with information as the log level so you can see it here and if i change this to warning the the minimum level then it's gonna execute again and print nothing because the log level is again higher than what we're actually logging and i'm gonna use this use case to run a memory profiler now for this to actually print something meaningful we have to run this for quite a long time or quite a few iterations so we're gonna move that over here and i'm gonna change this to that here we go and now if i run that let's see for how long it would run in the console so this is running still running still running i can hear my cpu still running and that's finished so it runs for let's say five to ten seconds which is more than enough now do you see this color being shown here which is quite different than anything you've seen before in my id well if i hover over that you can see that it detected two issues and it tells me that this allocated what is three gigabytes or 3.6 gigabytes of memory during that execution even though nothing was printed now let's take a look at this in in more detail right and for that we're going to use dot memory which is another jetbrains tool i'm using to profile the memory of my applications um it doesn't have a dark theme and it doesn't have a font increase functionality so you're gonna be blinded in three two one now sorry for that now what i can do with this is i can execute my application through this and see the memory and see how the memory is allocated managed and managed um heap generations garbage collection all that good stuff so i'm going to try to zoom in here and i'm gonna go ahead and show you how to use it so i'm gonna press the add button here then i'm gonna find my.net core application in the path and i'm gonna go to the bin release.net six location and i'm gonna select the exe so i'm gonna double click that i'm gonna say save and if i zoom back you can see this now loaded and over here i'm gonna use full the process filter is the default and the control of the profiling is manual and now i'm going to just press the start button and watch what happens here you see this going up and then down and up and down and up and down over here these orange things down here these orange small dots let me just stop this this this this this this these are garbage collections it's points in time where dot net is just clearing the memory and it effectively pauses the application to clean up the memory because pressure is being built and if i stop showing and manage memory you can see how it's going higher pressure is happening and then it's gobs collecting and if i actually collect a few snapshots so i have this snapshot here then let's have another one and then in a second let's have another one so i can now kill this process and as you can see during this execution let's say this block over here we allocated let me just zoom in up here 1.4 gigabytes of memory so this was only halfway through its execution and in 52 seconds of execution the gc time was two seconds this is a low-blooded gc time because that's time the app is doing nothing imagine in a single minute if you're building a game like a game server that the server pauses and does nothing for that time imagine if it's an fps how bad of an experience this will have and this obviously scales with anything you're doing on the high throughput scenario so we're not talking small numbers here yes i'm doing many iterations but we didn't even get through half of those in this execution and if i click on the snapshot i can drill into what is being allocated but i know what it's being allocated it is it is this so i don't need to drill into anything really now if i was to change that and had the if logger is enabled thing and i said log information and i put that over here and now i rebuilt it here we go went back to dot memory and i started it again watch what happens now that's it it's finished it went through 69 million and it's done i didn't cut it just did it because none of that memory was ever allocated it iterated over that um it may be allocated something here and initially to bootstrap the application and that's it it's done so you can see what difference this thing can actually make now something else which is a bit of a bonus point is that if you are using string interpolation here so you're doing something like that that's also very very bad watch why this is very bad i'm gonna go ahead and comment out this in fact this is worse than doing the boxing and array allocation thing because in here you're allocating a new string every single time while in reality this should be treated as a template not as the message and any parameters should be added as you know the way i showed before the way where you have a parameter and then the value in the parameters array let's see if i built this how the memory performs now here so i'm gonna go back at this one and re-run it and as you can see we have way more garbage collection now let's get a snapshot here um the memory is loading up way faster because strings are more expensive and you can see let's just let it run for a little bit uh let's get another snapshot the reason why the memory drops after the snapshot is because it is triggering a garbage collection um so don't be fooled by that i mean we're running for quite a long time so i think i can now just i kill the process and if i select all that this is 2.3 gigabytes of memory in a shorter period of time remember before let me just zoom in before it was 60 seconds and we had two seconds of agave's collection but only one point something when it comes down to memory this is way way more memory because strings are so much more expensive so if you are using string interpolation in your logging bad don't you really want to use the parameter based approach because in that way you only allocate the string template once and then the parameters are being added by the framework behind the scenes so that's a better way to do it now how do you fix it without just using is enabled everywhere because there is a compromise here well what you can do and i'm going to go in the benchmarks project and add it here is create a logger adapter and this is really relevant if you're not using serilog i will explain why but if you're using the built-in microsoft um logger you really should take a look at this so i logger adapter here and an adapter effectively will wrap our logger calls that's for two reasons first it's very hard to mock the i logger interface because it's calling into internal and classes so it's a bit clunky but it also allows us to do the following normally by default you have this log information call here which is just a string which is a message which is really the message template and let's go ahead and add the i logger adapter here and i can change that to use the same generic t type parameter if we want to so let's do that and then you can have the same log information thing but instead of using a parameters array we're going to use generics so we're going to say og0 and i'm going to put that here so t0 then t0 then t1 og 1 and put that here and then same for this one t1 t2 and usually you're going to have up to three arguments most common scenarios it's very uncommon you're going to have more but you definitely can it's not like impossible but i'm only going to keep it to three generic parameters in this scenario for now so you have something like that and then you're going to implement those members and then what you want to do is you want to have a private i logger of t which is your actual logger behind the scenes and inject that from the constructor and the way you want to implement those methods is as follows you want to say if logger dot is enabled and then obviously because you know that this is log information you're going to change that log information then you can now say logger dot log information message so that's what you have and now you can copy that to every other call so do that do that and do that and then this is arg0 here this is arg0 and then arg one and this is arg0 arg1 and og2 why is this a game changer in that context well first let me just duplicate that and create one with parameters and change that to log adapter here so i'm gonna go up here and say private read-only i logger adapter for benchmarking i'm going to say log adapter and i'm going to initialize it using the logger we just initialized i'm going to say new log adapter logger here we go now when i go down here and i can delete actually this is enabled thing i can simply say logger adapter dot log information and then have my same call and now because these values aren't actually boxed and allocated in an array they just passed as generics they won't get boxed and located on the hip in an array let's see how that looks like i'm going to go ahead and run these benchmarks again and let's wait for the results and see what we have so results are back and let's see what we have here so here's what i was talking about before remember how this and this had a big discrepancy between the performance but now they're the same i think previously the execution of this benchmark was picked up by a weak core on my cpu which is fine you can see that they perform exactly the same but you can see the difference of the um with parameters and without the f um this name of this benchmark is wrong actually this doesn't have the if but is nine nanoseconds so a bit more than double the the width if approaches but there is no memory allocation because these are passed down as generics so they stay as value types and because i have the if check over here they're never actually allocated until they need to be allocated in an array which is the valid use case so this solution is probably the best middle ground solution you're gonna go with because memory will hurt you way more than this being four or nine nanoseconds if you ever need to optimize further for speed then know that if you have the is enabled call higher so outside this method um it will be better because you don't even have to deal with the method call but for most people this solution will fix the problem and in fact it is exactly what serilog a very popular logging solution for net is doing if you go to any of their methods they actually use the same generic approach and they have t 0 t 1 t 0 t 1 t t 2 and for anything higher than that they have a parameters object array and if i go into their implementations for any of these that's what they do they have the is enabled check to avoid the allocation because they know that this is expensive and then they allocate all values here and again if you need you can go with four parameters but most likely they've done the research and they know that most log messages will log up to three arguments so that's how you can fix it and that's also the solution i would recommend to most people just to give you an idea if i go to the cellular project and i add the same looping mechanism but without the is enabled thing so just trust basically their code base to do its thing and then i build it and i go back to dot memory sorry for being blind again and i add that application so here we go and i before i forget i change this to warning so to ignore it basically and i rebuild that and here is serilog if i go ahead and run this then as you can see execution completed same graph as before because the thing is completely ignored that's why serilog might come out as more efficient by default compared to the default microsoft one because it has that check that makes it not allocate this unnecessary memory sorry for the longer video but i do think it's important to understand those things because login is such a fundamental thing in our code bases and it's so easy to also misuse it which is maybe a topic for another video that can really harm your application's performance well that's all i have for you for this video thank you very much for watching special thanks to my patreons for making this videos possible if you want to support me as well you're going to find the link in 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

Channel: Nick Chapsas

Views: 130,444

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

Id: bnVfrd3lRv8

Length: 25min 28sec (1528 seconds)

Published: Thu Jan 06 2022