FileTarget: Reset reusable MemoryStream when above max capacity

[RomanSoloweow]

Implementation for old feature request #4558.

Context:
We have rest logging (we log all requests and responses) and sometimes size of response can reach 4 megabytes or more. We came across the fact that logging requires about 400 megabytes of RAM. Here's what we found:

1. For some reason, the size of the StringBuilder used to write to memoryStream is 2-3 times larger than the original LogEvent message
2. If current MemoryStream.Capacity < StringBuilder.Length - capacity increases by 3 times from StringBuilder.Length
3. In come cases MemoryStream.Capacity still increases, despite that MemoryStream.Capacity > StringBuilder.Length
4. As a result of all these increases, a 3.5 megabyte log record results in stream capacity exceeding 80 megabytes.

After testing this fix, the amount of memory consumed was reduced by 5 times: 750 megabytes vs 150.
I think this fix will reduce memory consumption for users logging large messages. Those who log large messages constantly can increase capacity

[snakefoot]

I like the idea of not exploding into huge memory-usage after handling a single crazy LogEvent.

But I prefer just discarding crazy-large objects (Larger than ex. 128 KByte), instead of constantly trying to re-assign the original capacity (Similar to the internal NLog StringBuilderPool)

[RomanSoloweow]

We quite improved our research:

1. We log big response ~ 14.5 MB
2. Stream capacity increased 3X (~ 43.5 MB). Because Encoding.GetMaxByteSize return 3 time size for UTF8 case.

After that

1. We log new big response ~ 14.7 MB
2. Stream capacity increased 3X (~ 44.1 MB) because Encoding.GetMaxByteSize
3. Stream capacity increased 2X (~ 88.2 MB) because MemoryStream allocate 2 time more size by default.

It's mean that finally we got 6X overhead

[RomanSoloweow]

@snakefoot I understand your idea of ​​avoiding logging large messages, but a 6x increase just sounds crazy 🤯

Let me remind you that this logic per FIleTarget, of which there can be many (more than 10 in our case)

[snakefoot]

I'm not rejecting the idea of better memory-usage after handling crazy large LogEvent. Actually I would really like to make it better :)

I'm just saying that your initial pull-request can be improved (Avoid constantly re-assigning initial Capacity), and have guided you towards looking at the internal NLog StringBuilderPool (That discards crazy large objects, instead of keeping them alive forever).

[snakefoot]

Notice when I say "discarding crazy large objects" then it doesn't mean "discarding large logevents", but that reusable-objects (StringBuilder / MemoryStream) that have grown crazy large should be discarded (start from fresh, similar to how it is done by NLog StringBuilderPool).

[RomanSoloweow]

I think your idea close to RecyclableMemoryStream. What are you think about it?

[snakefoot]

@RomanSoloweow I think your idea close to RecyclableMemoryStream. What are you think about it?

Like that NLog has no dependencies, so would prefer improving the existing ReusableObjectCreator (Having the ability to start from fresh, similar to how it is done by NLog StringBuilderPool):

• NLog/src/NLog/Internal/ObjectPools/StringBuilderPool.cs

  Lines 94 to 100 in 15d6578

  	if (stringBuilder.Length > _maxBuilderCapacity)
  	{
  	// Avoid high memory usage by not keeping huge StringBuilders alive (Except one StringBuilder)
  	int maxBuilderCapacity = poolIndex == -1 ? _maxBuilderCapacity * 10 : _maxBuilderCapacity;
  	if (stringBuilder.Length > maxBuilderCapacity)
  	{
  	stringBuilder.Remove(0, stringBuilder.Length - 1); // Attempt soft clear that skips re-allocation

[snakefoot]

Notice when I say "similar to NLog StringBuilderPool", then it doesn't mean that ReusableBuilderCreator should be changed into a full-blown-objectpool. I'm just saying that one should take the logic for resetting an object, and extract into a seperate method, which then can be called by both NLog StringBuilderPool and ReusableBuilderCreator (Similar to how both call ClearBuilder).

[RomanSoloweow]

Already started implementing Pool based stream 😅

[snakefoot]

Yes sorry about the confusion. I have tendency to expect people to be mind-readers, and whatever that is crystal clear to me, should also be crystal clear to others :)

[RomanSoloweow]

Please review BufferPool before i will start inroduce it. I would like to write a couple of tests, but it seems that writing tests on Pools is not very common

[RomanSoloweow]

Some Benchmarks

Original NLog

With BufferPool

[snakefoot]

I'm surprised that it is possible to build something that is faster than the standard MemoryStream. Need to test this myself.

The object-pool in NLog has been about reusing the existing .NET building-blocks, and not trying to create our own to maintain.

So I'm a little reluctant going down this road of building our own Stream-class.

Notice I will be going on vacation now, so expect less feedback

[RomanSoloweow]

In this case, we will reuse existing buffers as long as we do not exceed the expected size. If exceeded, we will release excess memory. I think this will help us avoid endless memory growth due to one large message

The object-pool in NLog has been about reusing the existing .NET building-blocks, and not trying to create our own to maintain.

[RomanSoloweow]

No problem. Enjoy your vacation 🙏

Notice I will be going on vacation now, so expect less feedback

[RomanSoloweow]

@snakefoot hi, any news? What's the next?

[snakefoot]

I have created #5561 that tries to improve the Large-Object-Heap-handling for NLog. Each FileTarget should now have max-memory-usage of 10 MByte. Thus 7 FileTargets = 70 MByte.

Either you can enroll my suggestions in your pull-request, or I can merge my pull-request and close this one.

[RomanSoloweow]

I fill enroll your suggestions

[RomanSoloweow]

new tests:

Original:

With changes:

[snakefoot]

And do you approve of the new memory behavior, after handling a huge LogEvent?

[RomanSoloweow]

Summarizing:

StringBuilder is initialized with a size of 40 KB. After exceeding the maximum size of 400 KB, capacity will be reset to 40 KB.
MemoryStream is initialized with a size of 4 KB. After exceeding the maximum size of 9.5 MB, capacity will be reset to 80 KB.

[RomanSoloweow]

I believe this is a strong step forward, and we will be able to improve the values in the future. So yes, I agree and approve new behavior.

[snakefoot]

Notice that a single unicode char is 2 bytes. So your Stringbuilder byte-values has to be multiplied by 2. Bur happy you approve, also like that the capacity reset now uses a memory size below 85 KByte to avoid the Large Object Heap (LOH) from the beginning.

[sonarqubecloud]

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
86.7% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarCloud

[snakefoot]

@RomanSoloweow Thank you for the contribution, and effort to improve the NLog code base.

[RomanSoloweow]

When is the new version planned to be released?

[snakefoot]

I'm guessing within a week or two. Trying to see if TargetWithContext can be improved, after being made aware that it allocates a little too eagerly.

[RomanSoloweow]

Thank you for your review and help in solving the problem!

[snakefoot]

NLog v5.3.3 has been released:

• https://www.nuget.org/packages/NLog/5.3.3