One of the problems with the string concatenation method is that it is done everytime. Imagine if the logging level was set to Warning so that information message are not routinely logged. WIth the string concatenation method you would be building up this string but not using it. Whereas with the template method you would call the logger with a string constant and it would immediately return because it's not interested in logging at that level.
Never used .NET logging but with my custom logger I check the log level before creating the log string. I guess you can easily do this also with .NET's logger.
Yea do not listen to this advice in almost every case. Structured logging is usually on info/verbose and interpolation will always happen and formatting and logging of params will only happen if the log level allows. Not a good video...
Funny, I fight in PRs to use structured logging and get rid of string concatenation or string interpolation, those guys are ruining my mission! Although, I fight for different reasons, I don't care about memory efficiency here because for me it's negligible - just want to have useful logs to save developer's time.
I'm in the same boat. Constantly commenting on PRs to use structured logging. Even if they didn't write the log line in the first place, if they are modifying old code that doesn't use structured logging, I will comment to fix it since they are already making changes to that class.
Was going to add the same. If you have any kind of logging analyser, structured logging allows it to aggregate on the template so that you easily can find the most common type of error instead of having to use regex to try to make sense of the logs.
Good job on the bait title :p. I watched this just out of curiosity because I'm a huge proponent of structured logging. You hit the nail on the head at every point, but I actually was not aware that composed strings are impermanent and repeatedly allocate, which really ratchets up the importance of doing this right!
3:00 about multiple enumerations costing memory - isn't it generally the opposite? With ToList you're forcing all items to be stored temporarily, which prevents the enumeration being processed multiple times but at the expense of memory... unless the enumeration process itself is also storing everything?
depending on the implementation of IEnumerable (which you shouldn't know/care about) you actually can't always enumerate multiple times, so you don't really have an option if you need to know the count before iterating
glad i planned to re-watch some of your videos on logging because i kept expecting you to show a benchmark that really pushed home the difference in memory allocation. But i'm sure you've already done that multiple times in talks and videos.
Hello. What's the difference between string "Found {ItemCount} items of category {ItemCategory}" with passing ItemCount and ItemCategory after (Found {ItemCount} items of category {ItemCategory}, ItemCount, ItemCategory), and $"Found {ItemCount} items of category {ItemCategory}" in structural logging and maybe in strings interpolation in general?
I'd literally just been talking with one of my colleagues about your video on structured logging, and then I see you've published a new video about it!
Great advice! Use logging as its supposed to be used to receive all its benefits. Logging is not supposed to be overheat on your project, but use it badly and it will be. I love using serilog, used to work with log4net before but now its almost always serilog.
I knew that already and pointed that out to my superior, but we currently have a normal string based logger - which does not support templates, i can't change it. But we are planning to fully migrate to serilog/microsoft logging, so when i can finally use the structured logging.
We only add log fields selectively as all our applications log to a central elastic index and we're cognizant of elastics field count limitations. Any suggestions on how to get around this? We're using serilog.
Okay, source generated logging is going into by tool belt for sure. In some application, I wrote extension methods for ILogger, which just passed a fixed log message with custom parameters passed in. Wanted to avoid writing the same message multiple times. But it sounds like Source Generated Logs were what I should've done.
My two cents if helps. Select, Where etc.. in linq are also called Deferred operators - as per multiple enumeration Nick said. (opposite are Immediate operators i.e. ToList, ToArray, Count...)
I love using Serilog with structured logs in a SQL Server table. However, there are so many people creating content on LinkedIn and elsewhere. It's really difficult to discern whose content is good. You see, Nick, there are many bad examples in the content of many developers. Thanks a lot for your LinkedIn Series.
Well, if you store them in a SQL Server table then you probably serialize the parameters to XML or JSON and you probably also have the "concatenated" message along with the template in separate columns. So you may not do those string concatenations yourself, but Serilog does them for you anyway.
It could be worth mentioning, that if your particular log level is not enabled it will skip processing of whatever was sent. In the linkedin example string has to be always allocated, regardless of whether it will be used later or not.
I think that's a bit of an assumption. When the log method is reached, even if not enabled, the compiler will still have to evaluate the function and its parameters before trying to run the function where an if statement has to be reached before returning to the executing thread. There will be no performance or memory saved by using an implicit string parameter.
I use Serilog and save the structured logs to a SQL Server table. The parameters are stored in an XML column. I never cared about performance that much for logging and so I always store every parameter, but I'm fairly sure in my particular scenario appending the parameter to the XML is more memory / CPU intensive than doing a simple string concatenation. The final computed string gets stored in the table too (along with the template and the parameters), so Serilog does the concatenation anyway.
@@rGunti thanks, that makes sense although it sounds ugly haha. Introducing a db call for every log output AND serialising it as XML, I don't think any string tricks will save you from that performance overhead.
@@gnack420 Yes, the table column is of XML type. And there isn't a DB call for every log, Serilog does batching. And what would save you from serializing them as XML is literally not needing to do so if you just concatenate the strings. The XML is used purely to store the structured log parameters. But no matter what format or data structure you use to store the parameters, the point is someone has to do that computation, it does not come for free. At best you may defer this to another sever (the "logging service"), given of course that you use a very efficient communication protocol (if you just send JSON to that server then again it is pointless because your web server has to do the serialization there).
I dont understand does it actually matter if you declare a local string variable in your method? like how many times and how quickly would that method have to be called for that to matter? I never considered it as a problem, but i also never measured it. Is this not a micro-optimization? Would be interested to know any facts about when it could become a problem.
I got into the problem recently. Imagine a situation where you log into json which then goes to elastic (lets say through logstash). And at the same time imagine you capture a lot of different information, but not everything you want to index in Kibana as separate fields. How to overcome this? I came up with a simple solution of having some prefix and inside a custom formatter filter those fields with prefix and not include them in final json. But is there a better way? Also imagine there are many developers working on project and each use little bit different name for template for basically same information. This will result into indexing two separate fields for same information. Is there a way to define the property template name (e.g. {ItemCount}) as a constant string? lets say define in some file of those constants?
I have a question: Why are using people "ToList()" so often in Line, instead of "ToArray()". I mean 99% of the time (or more) you don't change the list ever again, so is an array not the better choice for this?
Most logging is kind of weak. A web application I worked on back in the day had logging that had been designed in from the start. Many users could be performing a variety of tasks simultaneously and the application couldn't really be taken down willy-nilly. It wrote to CSV files (this was 20 years ago) with a bunch of defined fields (ProcessID, ThreadID, SubsystemID, Severity, and a few more, and then the payload string which was the log message) and you could change how much and which subsystems were logging while it was running without shutting the application down. Turn logging up, do what was needed to reproduce a problem, turn logging back down, take the log file(s) of interest, load into Excel or a database and then use queries to get logging by ProcessID, ThreadID, SubsystemID, etc. as needed and drill down to see what was going on. Very, very useful. Most logging these days is just a big bunch of soup ;)
I guess this example isn't the best one to demonstrate the problem. But if I understood correctly the latter one is bad because it will potentially create new strings A LOT when the first one creates just one string template and those values that are added into that template? Depending which one you use doesn't affect for example how much disk space logs take but logs are easier to search through with these set values.
Is Source Genereated Logging, better than using something like Serilog? Or do you use it along side something like Serilog? (Why you would do that Idk.). As always Nick, great video!
Did not know that about logging! Application insights has been moaning at me too saying our WebApi is spending more than the recommended amount of resources on logging, this is probably one reason why. Time to go refactor…
Generally one should use a guard "if( Logger.IsEnabled( LogLevel.Information ) ){ Logger.LogInformation(...." so that you avoid the string manipulation entirely if the logging level doesn't require the message. This is most important for Debug level messages. The cost of the boolean check is very low compared to the allocation of strings.
@@gnack420 I looked at the source for Microsoft.Extensions.Logging.Logger and it's actually performing that check for you first, so you're right, it would be redundant if you're using dependency injection to attach an ILogger. Log4net used to require you to make the check on your own if you didn't want to trigger the formatter.
I have a feeling they use the well known spiel of providing missinformation to stir up conversation at the expense of less experienced developers who won't know better. (Thank go we have Code Cop) Also shows the point that if you want to learn something, post completely incorrect information online and watch it being corrected.
If you use string interpolation in a logger method, your IDE (whether Visual Studio or Rider, both do this) will give you a warning telling you to change it to structured logging. There’s no excuse not to do it.
You mean string concatenation (joining together multiple separate strings to form one string). String interpolation (using one template string and interpolating variables into that string) is what structured logging uses and is the correct/performant way to do things.
Isn't it even worse ? If you do "blabla" + variable + "blalba", you allocate at least 2 strings, right? one for "blabla" + variable and another for [the result of "blabla" + variable] + "blabla". Possibly 3 strings if ToString has to be called on variable.
Id personally prefer if linkedin promoted everything than censored anything. I would possibly be fine with censoring if it was community driven but how...
I really wish i could make my boss allow to hire you. I want to make perfect code but I'm running out of people that can me teach things. Unfortunately they bought a bunch of Google assholes that try to push go lang and gcp despite the fact we already have a capable cloud
Really to me the advice sounds like it came from a good intention but eventually misses the mark. My assumption is that the creator of this post basically heard somewhere that using params is bad when it's a params object due to boxing. And of course it is bad. But then the author proceeds to forget about the string allocations which are even worse and that's how I assume we ended up with this bad advice.
Listen to the advise and do vise-versa. Assume, dude « found » the advise to only made the video. When you try to find all the logs following his “advise “ - you will have to query by piece of the log and consequently either loose some of the logs or have to figure out the right pattern
I never liked the Logger system, I always end up making my own very simple logger class with no overhead. 🙂 But I agree with all that is said in the video.
I think all these Linkedin advices and written so badly on purpose to trigger comments and promote them. Like you need to have some basic knowledge to come up with such a reasoning behind so wrong idea
This is probably the most confusing video you've ever made. To be clear, you are saying structured logging is "good" despite being labeled "bad" just about everywhere else in the video.
One of the problems with the string concatenation method is that it is done everytime. Imagine if the logging level was set to Warning so that information message are not routinely logged. WIth the string concatenation method you would be building up this string but not using it. Whereas with the template method you would call the logger with a string constant and it would immediately return because it's not interested in logging at that level.
Never used .NET logging but with my custom logger I check the log level before creating the log string. I guess you can easily do this also with .NET's logger.
Yea do not listen to this advice in almost every case. Structured logging is usually on info/verbose and interpolation will always happen and formatting and logging of params will only happen if the log level allows. Not a good video...
@@brandonseydel3053xD
Searching logs for a fix template is also incredibly useful. Filtering JSON logs when concatenated values are used is a nightmare.
Glad to see I haven't been missing out on anything ever since I deleted my LinkedIn account 4 years ago
Funny, I fight in PRs to use structured logging and get rid of string concatenation or string interpolation, those guys are ruining my mission!
Although, I fight for different reasons, I don't care about memory efficiency here because for me it's negligible - just want to have useful logs to save developer's time.
I'm in the same boat. Constantly commenting on PRs to use structured logging. Even if they didn't write the log line in the first place, if they are modifying old code that doesn't use structured logging, I will comment to fix it since they are already making changes to that class.
Yup, if you see unstructured logging you have to fix it on the spot.
Was going to add the same. If you have any kind of logging analyser, structured logging allows it to aggregate on the template so that you easily can find the most common type of error instead of having to use regex to try to make sense of the logs.
Good job on the bait title :p.
I watched this just out of curiosity because I'm a huge proponent of structured logging.
You hit the nail on the head at every point, but I actually was not aware that composed strings are impermanent and repeatedly allocate, which really ratchets up the importance of doing this right!
3:00 about multiple enumerations costing memory - isn't it generally the opposite? With ToList you're forcing all items to be stored temporarily, which prevents the enumeration being processed multiple times but at the expense of memory... unless the enumeration process itself is also storing everything?
depending on the implementation of IEnumerable (which you shouldn't know/care about) you actually can't always enumerate multiple times, so you don't really have an option if you need to know the count before iterating
glad i planned to re-watch some of your videos on logging because i kept expecting you to show a benchmark that really pushed home the difference in memory allocation. But i'm sure you've already done that multiple times in talks and videos.
Hello. What's the difference between string "Found {ItemCount} items of category {ItemCategory}" with passing ItemCount and ItemCategory after (Found {ItemCount} items of category {ItemCategory}, ItemCount, ItemCategory),
and $"Found {ItemCount} items of category {ItemCategory}" in structural logging and maybe in strings interpolation in general?
I'd literally just been talking with one of my colleagues about your video on structured logging, and then I see you've published a new video about it!
I was waiting for the standard Benchmark runs and reports, like you normally do. Including a version with the Log extension. 😞 🙂
I hope you keep this series up because it is very beneficial.
Great advice! Use logging as its supposed to be used to receive all its benefits. Logging is not supposed to be overheat on your project, but use it badly and it will be.
I love using serilog, used to work with log4net before but now its almost always serilog.
I literally just took your dometrain logging course yesterday, so the title of this video made me laugh out loud. 😂😂
Omg, I had no idea the allocation optimization around using the templates! Where can I find out more about it, thankss
I knew that already and pointed that out to my superior, but we currently have a normal string based logger - which does not support templates, i can't change it.
But we are planning to fully migrate to serilog/microsoft logging, so when i can finally use the structured logging.
We only add log fields selectively as all our applications log to a central elastic index and we're cognizant of elastics field count limitations.
Any suggestions on how to get around this? We're using serilog.
Okay, source generated logging is going into by tool belt for sure. In some application, I wrote extension methods for ILogger, which just passed a fixed log message with custom parameters passed in. Wanted to avoid writing the same message multiple times. But it sounds like Source Generated Logs were what I should've done.
My two cents if helps. Select, Where etc.. in linq are also called Deferred operators - as per multiple enumeration Nick said.
(opposite are Immediate operators i.e. ToList, ToArray, Count...)
I love using Serilog with structured logs in a SQL Server table. However, there are so many people creating content on LinkedIn and elsewhere. It's really difficult to discern whose content is good. You see, Nick, there are many bad examples in the content of many developers. Thanks a lot for your LinkedIn Series.
Well, if you store them in a SQL Server table then you probably serialize the parameters to XML or JSON and you probably also have the "concatenated" message along with the template in separate columns.
So you may not do those string concatenations yourself, but Serilog does them for you anyway.
Whar about using $({variable}) approach , is this also impacts performance?
It could be worth mentioning, that if your particular log level is not enabled it will skip processing of whatever was sent. In the linkedin example string has to be always allocated, regardless of whether it will be used later or not.
I think that's a bit of an assumption. When the log method is reached, even if not enabled, the compiler will still have to evaluate the function and its parameters before trying to run the function where an if statement has to be reached before returning to the executing thread. There will be no performance or memory saved by using an implicit string parameter.
What we do here is go back...
Haha glad those times are over
I use Serilog and save the structured logs to a SQL Server table. The parameters are stored in an XML column. I never cared about performance that much for logging and so I always store every parameter, but I'm fairly sure in my particular scenario appending the parameter to the XML is more memory / CPU intensive than doing a simple string concatenation.
The final computed string gets stored in the table too (along with the template and the parameters), so Serilog does the concatenation anyway.
XML doesn't have columns, I don't follow what you're trying to say.
@@gnack420 I assume, SQL Server has a datatype to store XML data in it and that is what they meant.
@@rGunti thanks, that makes sense although it sounds ugly haha. Introducing a db call for every log output AND serialising it as XML, I don't think any string tricks will save you from that performance overhead.
@@gnack420 Yes, the table column is of XML type. And there isn't a DB call for every log, Serilog does batching.
And what would save you from serializing them as XML is literally not needing to do so if you just concatenate the strings. The XML is used purely to store the structured log parameters.
But no matter what format or data structure you use to store the parameters, the point is someone has to do that computation, it does not come for free. At best you may defer this to another sever (the "logging service"), given of course that you use a very efficient communication protocol (if you just send JSON to that server then again it is pointless because your web server has to do the serialization there).
1:45 that advice probably came from someone watching your earlier vids on the issues with structured logging and the alternatives 😅
HI Nick, have you ever written or made videos about frequent Azure Cosmos DB Mistakes?
Why benchmark is missing here...
I dont understand does it actually matter if you declare a local string variable in your method? like how many times and how quickly would that method have to be called for that to matter? I never considered it as a problem, but i also never measured it. Is this not a micro-optimization? Would be interested to know any facts about when it could become a problem.
You'll also miss out on the param formatting (numbers show different colour) in the log viewer if you don't use structured logging.
How can we make an Intellisense rule that will change my Interpolated strings to Structured?
I'm pretty sure that Rider already has one
You know, "Content Cop" ain't wrong ;)
2:21 Where link? :(
Can you make videos on custom CLI for .Net applications
The text says 6. episode but the creepy man in the video corner says 3. episode. Now I'm confused and crying
I got into the problem recently. Imagine a situation where you log into json which then goes to elastic (lets say through logstash). And at the same time imagine you capture a lot of different information, but not everything you want to index in Kibana as separate fields. How to overcome this? I came up with a simple solution of having some prefix and inside a custom formatter filter those fields with prefix and not include them in final json. But is there a better way? Also imagine there are many developers working on project and each use little bit different name for template for basically same information. This will result into indexing two separate fields for same information. Is there a way to define the property template name (e.g. {ItemCount}) as a constant string? lets say define in some file of those constants?
Please do one about the Composition is better than Inheritance argument. PS this is a Log Injection Attack
I have a question: Why are using people "ToList()" so often in Line, instead of "ToArray()". I mean 99% of the time (or more) you don't change the list ever again, so is an array not the better choice for this?
Did u find the answer?:)
@@kkk-tk6gq No, not really. Could be, that list has different set of member functions like sort. But other than that 🤷
This suggestion is so bad that I will not even bother to watch the full video lol. That is strange as your videos are great.
Most logging is kind of weak. A web application I worked on back in the day had logging that had been designed in from the start. Many users could be performing a variety of tasks simultaneously and the application couldn't really be taken down willy-nilly. It wrote to CSV files (this was 20 years ago) with a bunch of defined fields (ProcessID, ThreadID, SubsystemID, Severity, and a few more, and then the payload string which was the log message) and you could change how much and which subsystems were logging while it was running without shutting the application down. Turn logging up, do what was needed to reproduce a problem, turn logging back down, take the log file(s) of interest, load into Excel or a database and then use queries to get logging by ProcessID, ThreadID, SubsystemID, etc. as needed and drill down to see what was going on. Very, very useful. Most logging these days is just a big bunch of soup ;)
I guess this example isn't the best one to demonstrate the problem. But if I understood correctly the latter one is bad because it will potentially create new strings A LOT when the first one creates just one string template and those values that are added into that template? Depending which one you use doesn't affect for example how much disk space logs take but logs are easier to search through with these set values.
Is Source Genereated Logging, better than using something like Serilog? Or do you use it along side something like Serilog? (Why you would do that Idk.). As always Nick, great video!
Did not know that about logging! Application insights has been moaning at me too saying our WebApi is spending more than the recommended amount of resources on logging, this is probably one reason why. Time to go refactor…
Nice content bro, thanks
Idea for next video - Benchamrks: Json vs ProtoBuff vs Cap'n Proto vs MessagePack vs ...
Generally one should use a guard "if( Logger.IsEnabled( LogLevel.Information ) ){ Logger.LogInformation(...." so that you avoid the string manipulation entirely if the logging level doesn't require the message. This is most important for Debug level messages. The cost of the boolean check is very low compared to the allocation of strings.
There's no need for this if you use structured logging, it won't build the string unless it actually needs to output it.
@@gnack420 I looked at the source for Microsoft.Extensions.Logging.Logger and it's actually performing that check for you first, so you're right, it would be redundant if you're using dependency injection to attach an ILogger. Log4net used to require you to make the check on your own if you didn't want to trigger the formatter.
I've completed PR today that saves 3% allocations by using source generated logging.
Nick, why not add some benchmarks to make your point stronger.
Good reminder
Advice in LinkedIn posts is turning out the be the new Expert Village where virtually every single post is ass backwards wrong.
I have a feeling they use the well known spiel of providing missinformation to stir up conversation at the expense of less experienced developers who won't know better. (Thank go we have Code Cop)
Also shows the point that if you want to learn something, post completely incorrect information online and watch it being corrected.
Even better combine structured logging with the LoggerMessage attribute.
Hmm I agree 👍
If you use string interpolation in a logger method, your IDE (whether Visual Studio or Rider, both do this) will give you a warning telling you to change it to structured logging.
There’s no excuse not to do it.
You mean string concatenation (joining together multiple separate strings to form one string). String interpolation (using one template string and interpolating variables into that string) is what structured logging uses and is the correct/performant way to do things.
Hello everybody I'm Nick and welcome to the 3rd* episode of Intro Cop**
*1st
**Edit Cop
5:57 Oh boy. That comment might trigger the YAGNI abusers who showed up in the last video about braces. 😅
Isn't it even worse ?
If you do "blabla" + variable + "blalba", you allocate at least 2 strings, right? one for "blabla" + variable and another for [the result of "blabla" + variable] + "blabla".
Possibly 3 strings if ToString has to be called on variable.
Content Cop!?!? Someone looks like he has watched too much iDubbbzTV 🤪
Id personally prefer if linkedin promoted everything than censored anything. I would possibly be fine with censoring if it was community driven but how...
I really wish i could make my boss allow to hire you. I want to make perfect code but I'm running out of people that can me teach things. Unfortunately they bought a bunch of Google assholes that try to push go lang and gcp despite the fact we already have a capable cloud
omg no way u said content cop… idubz fan???
Really to me the advice sounds like it came from a good intention but eventually misses the mark.
My assumption is that the creator of this post basically heard somewhere that using params is bad when it's a params object due to boxing. And of course it is bad. But then the author proceeds to forget about the string allocations which are even worse and that's how I assume we ended up with this bad advice.
Listen to the advise and do vise-versa. Assume, dude « found » the advise to only made the video. When you try to find all the logs following his “advise “ - you will have to query by piece of the log and consequently either loose some of the logs or have to figure out the right pattern
Aaand if low level provider is badly written, then nothing helps you 😂
Take away? Learn ASM and know your computer's memory
I never liked the Logger system, I always end up making my own very simple logger class with no overhead. 🙂 But I agree with all that is said in the video.
No overhead? Are you sure about that?😊
@@mariocamspam72 Yeap, absolutely. 🙂
I think all these Linkedin advices and written so badly on purpose to trigger comments and promote them. Like you need to have some basic knowledge to come up with such a reasoning behind so wrong idea
This is probably the most confusing video you've ever made. To be clear, you are saying structured logging is "good" despite being labeled "bad" just about everywhere else in the video.
first!
Some of the "advice" from LinkedIn you've shown so far is really bad. I'm starting to think you're planting it to make videos 🤣
Nope these people exist.
I did not understand any of these. lol.