Do not mutate IEnumerable and null values when formatting #49228
Conversation
ghost
added
the
|
Tagging subscribers to this area: @maryamariyan Issue DetailsThis fixes #36165, #36025, and #48873. I tossed my first fix I did that checked the reference on every iteration in the loop and used the snippet @stephentoub proposed in the following discussion that was more elegant: #38734 Not sure the FormatQuick (naming is hard!) is really needed (a few more bytes allocated according to my tests), but the LoggerMessage is supposed to be used for high-performance logging scenarios, so maybe worth it anyways. I created a pull-request in benchmarks for related microbenchmarks: dotnet/performance#1708
|
|
The JsonConsoleFormatter (and any logging provider using the state) will have a breaking change now that the state is passed to the log provider exactly as provided, without being mutated (which, in my opinion, was a bug before and was the reason I filed #48873). Does this need to be added to any documentation/release notes if this pull-request is accepted? |
src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs
Outdated
Show resolved
Hide resolved
|
|
||
| // Assert | ||
| Assert.Single(testSink.Writes); | ||
| var write = testSink.Writes.First(); |
There was a problem hiding this comment.
var [](start = 12, length = 3)
please specify the type instead of var in the lines that is not clear what type the RHS will return
There was a problem hiding this comment.
I was a bit confused on if I should use var or not as I've read the coding guidelines for the dotnet repos that states that the type should be specified, but also to keep the existing style of a file, even if it breaks the guidelines.
In this case I copied the structure of the test from another test to keep the style consistent with the others, so that's why I kept using var here. I'll fix my added test to use explicit types, but leave the existing ones in the file as they are then?
| var param3 = new[] { 1, 2, 3, 4 }; | ||
| var param4 = "string"; | ||
|
|
||
| var logValues = new FormattedLogValues(format, param1, param2, param3, param4); |
There was a problem hiding this comment.
var [](start = 12, length = 3)
same, please use the type instead of var.
|
@pergardebrink the change looks good. Thanks for adding the benchmark for logging formatting too. could you please paste here some perf numbers before and after your changes showing the memory allocations? |
| { | ||
| object?[]? formattedValues = values; | ||
|
|
||
| if (values != null) |
There was a problem hiding this comment.
IMO there should be a comment here explaining why this is happening
There was a problem hiding this comment.
Explaining why it does an allocation of a new array in case the value would be changed? Yes, I'll add a comment about that!
| return string.Format(CultureInfo.InvariantCulture, _format, formattedValues ?? Array.Empty<object>()); | ||
| } | ||
|
|
||
| internal string FormatQuick(object?[]? values) |
There was a problem hiding this comment.
Should be a comment explaining when you can use FormatQuick vs Format
There was a problem hiding this comment.
Makes sense, I'll add a note to the FormatQuick/FormatWithOverwrite explaining that it mutates the array! Do you think it's necessary to have a note/hint about this method on the Format method as well?
src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs
Outdated
Show resolved
Hide resolved
src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs
Outdated
Show resolved
Hide resolved
|
@pergardebrink could you please address the remining feedback so we can move forward merging this PR? |
Is there any special scenarios you'd like to see? The benchmark I added to the performance repo for the case with enumerable parameter, along with existing ones look like the following, but I can run some extra variations on number of arguments. How many arguments to a log message would be interesting to see. In our codebase at our company, I'd say most log messages have on average 2-3, arguments up to a maximum of 10?: Before my changes:
After my changes:
|
|
Added local benchmark for 10 arguments with/without an enumerable also (the enumerable item, which was an int[9] array, came in position 5 in the array) Before my changes:
After my changes:
|
|
@pergardebrink thanks a lot for updating the code and getting the perf numbers. @davidfowl @stephentoub there is some extra allocations happening but this to fix the original concern. I am seeing the result is reasonable. do you have any feedback before we go ahead and merge this PR? |
|
As long as the extra allocations are when there's an enumerable then that's fine |
|
@pergardebrink thanks a lot for your help with this issue! |
6 participants
This fixes #36165, #36025, and #48873.
I tossed my first fix I did that checked the array reference on every iteration in the loop and used the snippet @stephentoub proposed in the following discussion that was more elegant: #38734
Not sure the FormatQuick (naming is hard!) is really needed (a few more bytes allocated according to my tests), but the LoggerMessage is supposed to be used for high-performance logging scenarios, so maybe worth it anyways.
I created a pull-request in benchmarks for related microbenchmarks: dotnet/performance#1708