Memory leak in Microsoft.Extensions.Logging.Internal.FormattedLogValues

[ghost]

The FormattedLogValues causes a serious memory leak. After a day about 1Gb of memory is wasted in my usage. The cause of the problem is:
private static ConcurrentDictionary<string, LogValuesFormatter> _formatters = new ConcurrentDictionary<string, LogValuesFormatter>();
...
...
_formatters.GetOrAdd(format, f => new LogValuesFormatter(f));

This code will just add objects and never clean them.

[glennc]

@meichtf Do you have some examples of what you are logging that fill up the cache? I would like to get the scenario right when we are choosing a fix.

It looks like the only way for this to happen is if you are doing something like combining string interpolation and string formatting, like _logger.LogInformation($"{DateTime.UtcNow} {{0}}", DateTime.UtcNow); is something like that what you are doing?

[ghost]

Yes, this is a good example you just provided. I know this is not a great usage of the API, but it should still not cause a leak.

[davidfowl]

That's really a bad use of the API, what are your actually doing in your application. There's obviously a trade off being made here. Regular usage of the API doesn't cause problem. It's possible we should just have an upper limit on the amount of values

[glennc]

An upper limit on the collection is what I proposed when we first looked at this, and I expect we will just do that. But I would like to see exactly what you are logging that is giving you the problem. If you put the values that are changing frequently in arguments then this problem goes away, is there a reason you can't or don't want to do that? or was it just that it didn't occur to you at the time? or something else?

[nblumhardt]

One other option to consider, but which I haven't tried it out, is to only cache formatters for interned strings (string.IsInterned(s)):

// Literals are interned; would be cached
"Hello {Name}"

// Generated strings are not interned; not cached
"Hello {Name}" + DateTime.UtcNow

Suggested originally by @jods4 IIRC.

Serilog uses an upper bound on the cache size currently, but might switch to this strategy or a hybrid one (cap the size for non-interned formats, but always allow interned formats to be added). Curious whether there are any obvious holes in it.

The Roslyn-based analyzer in https://github.com/Suchiman/SerilogAnalyzer detects usage of logging methods with non-constant templates - doing something similar for MEL, or broadening the SerilogAnalyzer project to cover it, would be the optimal solution I think :-)

[glennc]

@nblumhardt Can you split this suggestion into another issue to discuss? Even with this an unbounded cache is probably never a good idea, so we will add the max. But I am interested in the ideas enough to think about it in a different thread :).

[davidfowl]

.NET Core doesn't have string interning AFAIK.

[jods4]

@glennc

Even with this an unbounded cache is probably never a good idea, so we will add the max.

If you only cache interned strings, you cannot create a true memory leak, as those strings are guaranteed to be kept in memory, whether your cache exists or not. So basically, if there is a leak it exists in the application already.

Note that in a typical application the set of interned strings is determined at compile time and rarely (often never) changes.

@davidfowl
Interesting.
Are you speaking of the ability to intern additional strings at runtime or even just the concept?
When C# compiles a program, it dedupes all strings and interns them, does this not apply to a .NET Core build?

The use case I had in mind when I suggested that for NLog was to avoid this specific issue we have here. Proper usage of logging API should use constant strings and parameters; and compile-time constant strings are interned (at least in old-school .NET).

[davidfowl]

The APIs for checking whether a string is interned and the ability to call intern strings is gone.

/cc @jkotas

[jkotas]

It is there - once you upgrade to netcoreapp2.0:

https://github.com/dotnet/corefx/blob/5bd6dea77374feccbc859d4a771f9fff7e973d86/src/System.Runtime/ref/System.Runtime.cs#L2041

[BrennanConroy]

cc503aa