Reduce heap allocation of the default log message formatting logic in the FileLogger.Log

[aannenko]

The purpose of this PR is to reduce allocations done by FileLogger.Log() at run time.

Details

Profiling

Here's a simple Program.cs that logs 10000 messages:

using Microsoft.Extensions.Logging;
using NReco.Logging.File;

using var provider = new FileLoggerProvider("test.log");
var logger = new FileLogger("TestLogName", provider);

for (int i = 0; i < 10000; i++) {
	logger.Log(LogLevel.Information, "Test log message {number}", "1");
}

We can profile this program in Visual Studio with ".NET Object Allocation Tracking" enabled.

Here's how the profiling results look before the changes from this PR.
Note that for 10000 messages the code is allocating 40000 char arrays, ~30000 strings, 40000 StringBuilders and boxes 10000 EventIds, all of those allocations consume memory which leads to more frequent GCs.

In contrast, here are the results with these changes.
No char arrays, no StringBuilders, we no longer box EventIds and allocate one less string per log message.

Benchmark

BenchmarkDotNet results:

BenchmarkDotNet v0.14.0, Windows 11 (10.0.22631.4317/23H2/2023Update/SunValley3)
13th Gen Intel Core i9-13900K, 1 CPU, 32 logical and 24 physical cores
.NET SDK 8.0.403
  [Host]     : .NET 8.0.10 (8.0.1024.46610), X64 RyuJIT AVX2 [AttachedDebugger]
  DefaultJob : .NET 8.0.10 (8.0.1024.46610), X64 RyuJIT AVX2

Method	Mean	Ratio	RatioSD	Gen1	Allocated	Alloc Ratio
OriginalLoggerBenchmark	401.7 ns	1.00	0.03	0.0086	960 B	1.00
UpdatedLoggerBenchmark	390.9 ns	0.97	0.02	-	272 B	0.28

Expected outcome

These changes may prove useful in memory-constrained environments like docker containers, low-power devices (e.g. Raspberry), etc., as well as in high-thoughput scenarios where GC pressure is constantly high.

[aannenko]

All these packages in their version 8 are compiled for netstandard2.0, net6.0 and net8.0, so there's no need to create branches for separate frameworks.

[aannenko]

Stolen from https://github.com/dotnet/runtime/blob/main/src/libraries/Common/src/System/Text/ValueStringBuilder.cs

[aannenko]

Adapted from https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Number.Formatting.cs,566c4d2cd4ba9487

[aannenko]

Adapted from https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Globalization/DateTimeFormat.cs,24658c862fc77239

[VitaliyMF]

Looks good! Writing intesive logs via "Microsoft.Extensions.Logging" infrastructure is not a typical use case I guess (as ILogger interface is not designed for 'low-allocation' usage), however more optimal code is not a drawback for sure.

We definitely need to add more tests to ensure that optimized formatting 100% works as original one. Maybe it would be better to introduce a special FileLoggerOptions property to enable this optimization (and use original non-optimized default logs entry formatter by default)? This 100% can guarantee that this change will not affect existing lib users.

I can add tests by myself, this is not a problem. I just need a bit of free time for that.

[aannenko]

Writing intesive logs via "Microsoft.Extensions.Logging" infrastructure is not a typical use case I guess (as ILogger interface is not designed for 'low-allocation' usage)

True. Although, there are certain efforts to improve logging performance :)

1. https://learn.microsoft.com/en-us/dotnet/core/extensions/high-performance-logging
2. https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator

We definitely need to add more tests to ensure that optimized formatting 100% works as original one. [...] I can add tests by myself, this is not a problem. I just need a bit of free time for that.

Thank you!

Maybe it would be better to introduce a special FileLoggerOptions property to enable this optimization (and use original non-optimized default logs entry formatter by default)? This 100% can guarantee that this change will not affect existing lib users.

Makes sense. But, if tested thoroughly enough, I believe it also makes sense to switch to the optimized approach right away.
My manual testing included:

• calculation of the final message length, so that we don't go over the buffer size when building a log entry string (even if we went overboard, ValueStringBuilder would just rent a bigger buffer automatically, but that would defeat the purpose of this perf optimization PR)
• correctness of TryFormat and the other extension methods with various kinds of int (0, MinValue, MaxValue) and DateTime (default(DateTime), DateTimeKind.Local/UTC/Unspecified)
• equality of log messages between the old and new FileLogger

So, up to you to decide :)
If you want, I'll add a Boolean property named something along the lines of HighPerformanceDefaultMessageFormatter to FileLoggerOptions and add a class ValueFileLogger with the new logging behavior.

[aannenko]

Off-topic: there's one flaky test - WriteAscendingStableBaseRollingFile. It sometimes fails, sometimes passes.

[VitaliyMF]

WriteAscendingStableBaseRollingFile

This mode was added here by a contributor: #66
I also noticed that sometimes tests related to this commit can fail (in my dev env, I often see WriteDescendingRollingFile failed).
It seems the problem is not in the FileLoggerProvider logic, and caused by a test that relies on System.Threading.Thread.Sleep(20).

I've added #75 to fix this.

[VitaliyMF]

@aannenko Could you explain a motivation to remove references to 6.0.* for net6?
I understand that this is (almost) legacy as for now, however it might be possible that some users didn't migrate to net8 yet, so it makes sense to reference 6.0.* versions of Microsoft.* nugets.

[aannenko]

These packages are both shipped with a .NET runtime and exist as separate NuGet packages. Version 8 of the ones from NuGet, including Microsoft.Extensions.Logging and derivatives, directly targets netstandard2.0, net6.0 and net8.0 - the same frameworks that NReco.Logging.File targets. So as long as we target the same frameworks, we should not have any problems if we reference 8.0.* for all of these packages.

---

Some more thoughts.

Are there really benefits in locking a package version to a framework version?
One I can think of is you don't need to pull a package from NuGet because it's is included with a .NET runtime installation.
But there are also downsides:

• we ignore the improvements in the latest versions of a package
• we may miss potential CVE fixes merged into the newer versions of a package
• we may force an older version of Microsoft.Extensions.Logging onto a consumer of NReco.Logging.File when they want to use a newer one
• if the package consumer logs not only to file but also, say, to Elastic, we are more likely to create dependency conflicts with the Elastic logging provider

---

I also had a look at how a couple of popular NuGet packages do this:

Serilog. Uses 8.0.1 for all its targets.
https://github.com/serilog/serilog/blob/dev/src/Serilog/Serilog.csproj

MiniValidation. Targets net6.0, does not target net8.0 as of now, references the latest package versions anyway.
https://github.com/DamianEdwards/MiniValidation/blob/main/src/MiniValidation/MiniValidation.csproj
https://github.com/DamianEdwards/MiniValidation/blob/main/Directory.Packages.props

[VitaliyMF]

Policy for dependencies on other libs versions is a good topic for discussion. I don't think that "the best" policy ever exists -- more adequate answer, I guess, "it depends".

For "NReco.Logging.File", I think not using the latest version for old (legacy) targets makes sense.
Just imagine that you have net6 project, that still uses all Microsoft.* components from 6.0.* branch. MS guarantees that all these libs are compatible, however if you decide to use some library with newer version - say, 8.0.1, it can work correctly, but also can lead to potential instability - for instance, dependences can force implicit upgrades of another packages, and this can lead to "DLL hell". You may remember .NET Core 1.0 times when there was a try to release each framework part with own release cycle, and that causes this "DLL hell" on practice - so they back to .NET Framework-style releases, when net6.0 target by default uses 6.0.* framework libs, and net8.0 uses 8.0.* and so on.

Regarding

we may force an older version of Microsoft.Extensions.Logging onto a consumer of NReco.Logging.File when they want to use a newer one

If project has a reference to newer version of "Microsoft.Extensions.Logging", dependency on the lower version in NReco.Logging.File cannot force a downgrade.

I believe that when someone decides to use "NReco.Logging.File" this dependency should not cause upgrades of another dependencies implicitely, this is a safe behaviour that developers may expect. I agree that it is ok to reference 8.0.* for the netstandard2.0 target, but keep 6.0.* for legacy net6 (and 8.0.* for net8, when next net10 LTS becomes available).

[VitaliyMF]

I found a bit of time to review this PR, I have the following comments/propositions:

• all helper methods that are needed for this 'optimized' FormatLogEntry should not be public - like DateTimeExtensions or IntExtensions
• by changes in FileLogger.Log<TState> code it looks like this optimized formatter can be used just as an external FormatLogEntry handler (without affecting FileLogger code at all). This means that all new code can be moved to a special class - like OptimizedFormatLogEntry - and used only when needed. As I already mentioned, for many apps that don't write logs intensively, primitive StringBuilder-based default implementation is just good enough and allocation overhead simply doesn't matter. As I already said, I would like to keep it by default to guarantee 100% backward compatibility.

I can make these changes by myself, no need to change the PR.

[aannenko]

Ok, totally! Feel free to add changes to this PR and close it as you see fit :)

As for making the extension classes IntExtensions and DateTimeExtensions non-public. There's InternalsVisibleToAttribute, it can be used like so:

[assembly: InternalsVisibleTo("NReco.Logging.Tests")]

Or you can extract these extensions into a separate project that targets only netstandard2.0 and reference it only by the netstandard2.0 target of NReco.Logging.File.

reference 8.0.* for the netstandard2.0 target, but keep 6.0.* for legacy net6

I yield :)

[aannenko]

As for backward compatibility.
https://learn.microsoft.com/en-us/dotnet/core/compatibility/categories#backwards-compatibility

We did not really change any APIs, source and even binary compatibility are preserved, and from the user's standpoint the behavior is the same - and this can be checked manually and with tests. So we have full backward compatibility. Another concern is if the changes introduce new potential points of failure - which, again, can be addressed by covering the changes with tests, especially when the most significant changes are concentrated in one method of one class. This can be a good enough guarantee that nothing breaks.

If I were to decide, I would try switching to the optimized implementation and avoid exposing additional options in the app's settings. In such case all users would just receive a free perf boost without changing anything as they upgrade the package.

I myself, as a user of this package, very much like that it has minimalistic settings and sensible defaults. If I were at some point to find the information about a new configuration option that decreases heap allocation, I would certainly try it. So now I have +1 option configured for this package. What's next? Should I memorize that I need this option in every project where I use this logger? Will the code pertaining this option eventually replace the original? If so, what should I do with this option then? Will I still need it / will it still work?

Though, as I said earlier, you are the main package maintainer so it's up to you to decide.

[VitaliyMF]

@aannenko I reorganized the code and I decided to use your optimized implementation by default as you proposed, see 2396077:

• all code related to low-alloc log message formatting moved to StringLogEntryFormatter
• optimized IntExtensions.GetFormattedLength to avoid usage of Math.Floor / Math.Log10 at all
• added more tests

These changes are already shipped in 1.2.2
Thanks a lot for your contribution!

[aannenko]

@VitaliyMF this is awesome, thank you!