LoggerMessage formatter performance improvements #58524

Scooletz · 2021-09-01T20:31:20Z

Remark: This is still a draft, but before I spend a lot of time, I'd appreciate a soft yay or nay from people responsible for the logging area. It will take more time and it'd be great if I could get some initial feedback. The initials numbers are amazing, and being given that this PR targets LoggerMessage, which should be high-perf, this looks like a potential huge gain for all the loggers calling the formatter.

This PR is a result of profiling/benchmarking a piece of code that touched Durable Functions and used ApplicationInsight. I found that the logger, that is provided as the official package, calls formatter, having the state not only logged as usual key-value pairs but also as a formatted string.

https://github.com/microsoft/ApplicationInsights-dotnet/blob/d54bae8aeaf74b6fa08c8033c2ce54ea6d8f437b/LOGGING/src/ILogger/ApplicationInsightsLogger.cs#L113

https://github.com/microsoft/ApplicationInsights-dotnet/blob/d54bae8aeaf74b6fa08c8033c2ce54ea6d8f437b/LOGGING/src/ILogger/ApplicationInsightsLogger.cs#L94

The idea behind this PR would be to improve the formatter built by LoggerMessage by capturing much more context during the build up of LogValuesFormatter and to use it when formatting the value. I'm aware that LogValues should be kept small (big structs are no-no for perf) and this can be amended later on by capturing the formatting info into a separate object.

Benchmarks

Initial benchmarks, even with some functionality missing, looks extremely promising. Both the time and the allocations (no boxing!) are reduced

BenchmarkDotNet=v0.13.1, OS=Windows 10.0.19042.1165 (20H2/October2020Update)
Intel Core i7-6700HQ CPU 2.60GHz (Skylake), 1 CPU, 8 logical and 4 physical cores
.NET SDK=6.0.100-preview.7.21379.14
  [Host]     : .NET 6.0.0 (6.0.21.37719), X64 RyuJIT
  DefaultJob : .NET 6.0.0 (6.0.21.37719), X64 RyuJIT

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen 0	Allocated
'int32 logged with the template: "A value {Value}"'	113.28 ns	2.267 ns	2.425 ns	113.77 ns	1.00	0.00	0.0204	64 B
new 'int32 logged with the template: "A value {Value}"'	43.73 ns	0.847 ns	0.976 ns	43.61 ns	0.39	0.01	0.0127	40 B

'Guid logged with the template: "A value {Value}"'	149.22 ns	2.930 ns	3.488 ns	149.04 ns	1.00	0.00	0.0458	144 B
new 'Guid logged with the template: "A value {Value}"'	85.79 ns	1.723 ns	1.984 ns	86.04 ns	0.58	0.02	0.0356	112 B

'int32 logged with the template: "A value {Value} was used"'	146.91 ns	5.435 ns	15.419 ns	142.06 ns	1.00	0.00	0.0279	88 B
new 'int32 logged with the template: "A value {Value} was used"'	50.99 ns	1.024 ns	2.069 ns	50.44 ns	0.34	0.04	0.0204	64 B

'Guid logged with the template: "A value {Value} was used"'	176.59 ns	4.941 ns	13.855 ns	175.78 ns	1.00	0.00	0.0508	160 B
new 'Guid logged with the template: "A value {Value} was used"'	104.11 ns	4.137 ns	12.002 ns	102.65 ns	0.60	0.09	0.0408	128 B

ghost · 2021-09-01T20:31:28Z

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

Issue Details

Remark: This is still a draft, but before I spend a lot of time, I'd appreciate a soft yay or nay from people responsible for the logging area. It will take more time and it'd be great if I could get some initial feedback.

This PR is a result of profiling/benchmarking a piece of code that touched Durable Functions and used ApplicationInsights. I found that the logger that is provided as the official package calls formatter, having the state not only logged as usual key-value pairs but also as a formatted string.

https://github.com/microsoft/ApplicationInsights-dotnet/blob/d54bae8aeaf74b6fa08c8033c2ce54ea6d8f437b/LOGGING/src/ILogger/ApplicationInsightsLogger.cs#L113

https://github.com/microsoft/ApplicationInsights-dotnet/blob/d54bae8aeaf74b6fa08c8033c2ce54ea6d8f437b/LOGGING/src/ILogger/ApplicationInsightsLogger.cs#L94

The idea behind this PR would be to improve the formatter built by LoggerMessage by capturing much more context during the build up of LogValuesFormatter and to use it when formatting the value.

Benchmarks

Initial benchmarks, even with some functionality missing, looks extremely promising. Both the time and the allocations (no boxing!) are reduced

BenchmarkDotNet=v0.13.1, OS=Windows 10.0.19042.1165 (20H2/October2020Update)
Intel Core i7-6700HQ CPU 2.60GHz (Skylake), 1 CPU, 8 logical and 4 physical cores
.NET SDK=6.0.100-preview.7.21379.14
  [Host]     : .NET 6.0.0 (6.0.21.37719), X64 RyuJIT
  DefaultJob : .NET 6.0.0 (6.0.21.37719), X64 RyuJIT

Method	Mean	Error	StdDev	Median	Ratio	RatioSD	Gen 0	Allocated
'int32 logged with the template: "A value {Value}"'	113.28 ns	2.267 ns	2.425 ns	113.77 ns	1.00	0.00	0.0204	64 B
new 'int32 logged with the template: "A value {Value}"'	43.73 ns	0.847 ns	0.976 ns	43.61 ns	0.39	0.01	0.0127	40 B

'Guid logged with the template: "A value {Value}"'	149.22 ns	2.930 ns	3.488 ns	149.04 ns	1.00	0.00	0.0458	144 B
new 'Guid logged with the template: "A value {Value}"'	85.79 ns	1.723 ns	1.984 ns	86.04 ns	0.58	0.02	0.0356	112 B

'int32 logged with the template: "A value {Value} was used"'	146.91 ns	5.435 ns	15.419 ns	142.06 ns	1.00	0.00	0.0279	88 B
new 'int32 logged with the template: "A value {Value} was used"'	50.99 ns	1.024 ns	2.069 ns	50.44 ns	0.34	0.04	0.0204	64 B

'Guid logged with the template: "A value {Value} was used"'	176.59 ns	4.941 ns	13.855 ns	175.78 ns	1.00	0.00	0.0508	160 B
new 'Guid logged with the template: "A value {Value} was used"'	104.11 ns	4.137 ns	12.002 ns	102.65 ns	0.60	0.09	0.0408	128 B

Author:	Scooletz
Assignees:	-
Labels:	`area-Extensions-Logging`, `community-contribution`
Milestone:	-

Scooletz · 2021-09-03T09:51:22Z

@maryamariyan Thank you for chiming in. Looking forward for your opinion on whether this is something we want to pursue. This will require a lot of polishing, but the initial idea is in there. If you need any more input, ping me. I'm looking forward to hearing your opinion.

Scooletz · 2021-09-09T14:27:11Z

Any thoughts/opinions @maryamariyan ?

Scooletz · 2021-09-17T15:42:10Z

Could I get an update on this or ETA where I can expect some input whether to push forward with this?

Scooletz · 2021-09-21T13:37:05Z

It's been 20 days since a request to get some input. Could sb chime in and let me know whether this is something that has a possibility to be merged in? I don't want to propose sth to get it rejected.

danmoseley · 2021-09-21T13:44:07Z

It should not take this long.
@dotnet/area-extensions-logging @maryamariyan

eerhardt

I think this is an interesting idea. It may make sense pursue this more. It would be good to get the CI passing so we know that the change doesn't affect behavior.

Thoughts @davidfowl @pakrym ?

eerhardt · 2021-09-23T14:32:19Z

src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerMessage.cs

@@ -540,8 +585,24 @@ public LogValues(LogValuesFormatter formatter, T0 value0)
                }
            }

+            public override string ToString()
+            {
+                Span<char> output = stackalloc char[1024];


How do we know 1024 is big enough?

This should use ValueStringBuilder

It's not. This was just to please some initial tests and I'll need to amend it in a much smarter way 😄

eerhardt · 2021-09-23T14:33:10Z

src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerMessage.cs

+        [MethodImpl(MethodImplOptions.AggressiveInlining)]
+        private static int Append<TValue>(Span<char> span, TValue value, string format)
+        {
+            // ReSharper disable once MergeCastWithTypeCheck


What are these comments for?

Pleasing Resharper. Will remove.

eerhardt · 2021-09-23T14:34:25Z

src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerMessage.cs

+        private static int Append<TValue>(Span<char> span, TValue value, string format)
+        {
+            // ReSharper disable once MergeCastWithTypeCheck
+            if (value is ISpanFormattable)


Suggested change

if (value is ISpanFormattable)

if (value is ISpanFormattable spanFormattable)

I believe I was falling with having it JITted without boxing. It was a while ago. Will take a look at it and use the new syntax if possible.

Yes, today the JIT can't avoid boxing when using if (value is ISpanFormattable sf) { sf.TryFormat(...); } but it can when doing if (value is ISpanFormattable) { ((ISpanFormattable)value).TryFormat(...); }; the latter case is easier to prove correct.

Scooletz · 2021-09-23T14:56:50Z

Thx for chiming in @eerhardt . If this is looks like an initially interesting idea let me give it a spin and make CI green. Also, if there are some more opinions about it, let me know.

stephentoub · 2021-09-23T15:04:38Z

In #50330 we discussed using the proposed CompositeFormat as an implementation detail under LoggerMessage.Define. Is this essentially doing the same thing?

Scooletz · 2021-09-23T15:17:12Z

I wasn't aware of this beautiful proposal @stephentoub ! Actually, the case that I'm raising here, is mentioned in the original repo https://github.com/geeknoid/FastFormatting#template-based-format-strings ! Having this said, I'm closing this PR as the mentioned functionality is set to Future milestone. Logging will get this lunch for free 😅

initial

0713294

ghost added the community-contribution Indicates that the PR has been added by a community member label Sep 1, 2021

dotnet-issue-labeler bot added the area-Extensions-Logging label Sep 1, 2021

maryamariyan self-requested a review September 2, 2021 18:20

maryamariyan added this to the 7.0.0 milestone Sep 2, 2021

eerhardt reviewed Sep 23, 2021

View reviewed changes

Scooletz closed this Sep 23, 2021

Scooletz deleted the LoggerMessage-ToString-optimized branch September 23, 2021 15:17

ghost locked as resolved and limited conversation to collaborators Nov 3, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

LoggerMessage formatter performance improvements #58524

LoggerMessage formatter performance improvements #58524

Scooletz commented Sep 1, 2021 •

edited

Loading

ghost commented Sep 1, 2021

Benchmarks

Scooletz commented Sep 3, 2021 •

edited

Loading

Scooletz commented Sep 9, 2021

Scooletz commented Sep 17, 2021

Scooletz commented Sep 21, 2021

danmoseley commented Sep 21, 2021

eerhardt left a comment

eerhardt Sep 23, 2021

davidfowl Sep 23, 2021

Scooletz Sep 23, 2021

eerhardt Sep 23, 2021

Scooletz Sep 23, 2021

eerhardt Sep 23, 2021

Scooletz Sep 23, 2021

stephentoub Sep 23, 2021

Scooletz commented Sep 23, 2021

stephentoub commented Sep 23, 2021

Scooletz commented Sep 23, 2021

	if (value is ISpanFormattable)
	if (value is ISpanFormattable spanFormattable)

LoggerMessage formatter performance improvements #58524

LoggerMessage formatter performance improvements #58524

Conversation

Scooletz commented Sep 1, 2021 • edited Loading

Benchmarks

ghost commented Sep 1, 2021

Benchmarks

Scooletz commented Sep 3, 2021 • edited Loading

Scooletz commented Sep 9, 2021

Scooletz commented Sep 17, 2021

Scooletz commented Sep 21, 2021

danmoseley commented Sep 21, 2021

eerhardt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Scooletz commented Sep 23, 2021

stephentoub commented Sep 23, 2021

Scooletz commented Sep 23, 2021

Scooletz commented Sep 1, 2021 •

edited

Loading

Scooletz commented Sep 3, 2021 •

edited

Loading