Skip to content

Fix Log Formatter mutating its arguments. - #38734

Closed
vaz-rodrigo wants to merge 1 commit into
dotnet:masterfrom
vaz-rodrigo:issue-36165
Closed

Fix Log Formatter mutating its arguments.#38734
vaz-rodrigo wants to merge 1 commit into
dotnet:masterfrom
vaz-rodrigo:issue-36165

Conversation

@vaz-rodrigo

Copy link
Copy Markdown

Log Formatter now creates a new object array and inserts the formatted
parameters there instead of the original array.
Also added a test to verify if the types of the original objects remain
unchanged.

Fix #36165

Log Formatter now creates a new object array and inserts the formatted
parameters there instead of the original array.
Also added a test to verify if the types of the parameters remain
unchanged.

Fix #36165
@Dotnet-GitSync-Bot

Copy link
Copy Markdown
Collaborator

I couldn't figure out the best area label to add to this PR. If you have write-permissions please help me learn by adding exactly one area label.

@dnfadmin

dnfadmin commented Jul 3, 2020

Copy link
Copy Markdown

CLA assistant check
All CLA requirements met.

@stephentoub

Copy link
Copy Markdown
Member

@davidfowl expressed this concern in the linked issue:
"We should be aware of the performance implications here though since this is a pretty hot and main code path."

Have you validated that this doesn't measurably regress important usage?

{
object[] formattedValues = null;

if (values != null)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might values be Length == 0? There's no benefit allocating in that case.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, when the values array is either null or of length 0, the Log formatter is set to null and in that case, array formatting is skipped.

This does makes the check for a null array redundant, no?

for (int i = 0; i < values.Length; i++)
{
values[i] = FormatArgument(values[i]);
formattedValues[i] = FormatArgument(values[i]);

@stephentoub stephentoub Jul 3, 2020

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like FormatArgument will often just return the input, and if that's the case for all inputs, there's no benefit allocating an array. Seems like this would be better off lazily creating the new array the first time a formatted argument is a different reference than the input. (That will also implicitly take care of the empty case I mentioned.)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On top of that, it looks like this method has four call sites, three of which always pass in a brand new array, where it doesn't matter if the method modifies it. Seems like there should be a separate path for that, if this really is hot.

@vaz-rodrigo

Copy link
Copy Markdown
Author

davidfowl expressed this concern in the linked issue:
"We should be aware of the performance implications here though since this is a pretty hot and main code path."

Have you validated that this doesn't measurably regress important usage?

@stephentoub I'm running the dotnet/performance microbenchmarks now, on both the proposed solution and on a preliminary lazy-loaded version. What is the best way to share the benchmark results?

@stephentoub

Copy link
Copy Markdown
Member

I'm running the dotnet/performance microbenchmarks now

I doubt there's any coverage of this there. These libraries were only just moved to dotnet/runtime recently, and nothing else in dotnet/runtime will depend on these. I expect the perf impact would show up more in an ASP.NET application of some kind. But if nothing else, you could write a microbenchmark on the relevant types.

@davidfowl

Copy link
Copy Markdown
Member

I would write a new micro benchmark for this. I think doing the work to avoid the allocation in the very common case where the args aren’t modified is what I was originally thinking

@vaz-rodrigo

Copy link
Copy Markdown
Author

I would write a new micro benchmark for this. I think doing the work to avoid the allocation in the very common case where the args aren’t modified is what I was originally thinking

I wrote some benchmarks, should I try to do a PR on the benchmark repo or would you like me to add them here before that?

Also, I'm afraid that having to check every time if the returned object matches the reference of the original value to only then allocate the new array will not be effective, specially when an enumerable is the last item in the param array...

@stephentoub

Copy link
Copy Markdown
Member

Also, I'm afraid that having to check every time if the returned object matches the reference of the original value to only then allocate the new array will not be effective, specially when an enumerable is the last item in the param array

Why?

@stephentoub

Copy link
Copy Markdown
Member

To be clear, I'm suggesting it essentially be this:

public string Format(object[] values)
{
    object[] formattedValues = values;

    if (values != null)
    {
        for (int i = 0; i < values.Length; i++)
        {
            object formattedValue = FormatArgument(values[i]);
            if (!ReferenceEquals(values[i], formattedValue)
            {
                formattedValues = new object[values.Length];
                Array.Copy(values, 0, formattedValues, 0, i);
                formattedValues[i++] = formattedValue;
                for (; i < values.Length; i++)
                {
                    formattedValues[i] = FormatArgument(values[i]);
                }
                break;
            }
        }
    }

    return string.Format(CultureInfo.InvariantCulture, _format, formattedValues ?? Array.Empty<object>());
}

@ghost

ghost commented Aug 6, 2020

Copy link
Copy Markdown

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

@stephentoub

Copy link
Copy Markdown
Member

@vaz-rodrigo, are you still working on this?

@maryamariyan

Copy link
Copy Markdown
Contributor

Closing this PR. @vaz-rodrigo feel free to create a new PR with the recommended changes.

@ghost ghost locked as resolved and limited conversation to collaborators Dec 8, 2020
@vaz-rodrigo
vaz-rodrigo deleted the issue-36165 branch August 6, 2022 01:53
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

ILogger mutates the array of objects to format

6 participants