NLog Memory Leak with slow log writer

[grahambunce]

Type (choose one):

• Bug

NLog version: (e.g. 4.2.3)
4.4.12 and 4.5 (started with 4.4.12, tried an upgrade to 4.5)

Platform: .Net 4.6.1 (Azure Web App)

Current NLog config (xml or C#, if relevant)

    <extensions>
      <add assembly="NLog.AzureBlobStorage"/>
    </extensions>
    <targets>
      <target type="AsyncWrapper" name="logger" overflowAction="Grow">
        <target type="AzureAppendBlob" name="bloblog" connectionString="logs" container="logs"
          layout="${date:format=yyyy-MM-dd HH\:mm\:ss.fffff},${threadid},${logger},${message},${all-event-properties}"
          blobName="catalog-api\${date:universalTime=true:format=yyyy}/${date:universalTime=true:format=MM}/${date:universalTime=true:format=yyyy-MM-dd}/${date:universalTime=true:format=HH}:00.log"/>
      </target>
      <target type="AsyncWrapper" name="publisher" overflowAction="Grow">
        <target type="AzureAppendBlob" name="blobexception" connectionString="logs" container="logs"
          layout="${date:format=yyyy-MM-dd HH\:mm\:ss.fffff},${threadid},${exception:format=type}${newline}${exception:format=message}${newline}${event-properties:item=RootId},${event-properties:item=ParentId},${event-properties:item=Id}${newline}${exception:format=data}${newline}${newline}${exception:format=stacktrace}${newline}"
          blobName="catalog-api\${date:universalTime=true:format=yyyy}/${date:universalTime=true:format=MM}/${date:universalTime=true:format=yyyy-MM-dd}/${date:universalTime=true:format=HH}:00-exception.log"/>
      </target>
    </targets>
    <rules>
      <logger name="*" minlevel="Trace" writeTo="logger"/>
      <logger name="exception" minlevel="Error" writeTo="publisher" final="true"/>
    </rules>
  </nlog>

In case of a BUG:

• What is the current result?
  As load increases on the site, AppPool increases in memory usage. This memory is never released.

• What is the expected result?
  AppPool to increase in memory as load increases (due to buffering of logs) but then release this as load descreases

• Did you checked the Internal log?
  yes

• Please post full exception details (message, stacktrace, inner exceptions)
  n/a

• Are there any workarounds? yes/no
  no

• Is there a version in which it did work?
  no

• Can you help us by writing an unit test?
  n/a

I know there have been a number of NLog memory leak issues raised before (#2369 #2220 #2343 #1846 #316) and these have been closed. However, I don't think that they have been closed with a proper resolution, more like "a workaround has been found that works, I'll close it".

The workaround appears to be finding a way to increase throughput of the file logger. So, I guess, the logger could then keep pace with the logs so objects did not start to grow in the async logger buffer, therefore the problem goes away.

In our case, we're using a custom Azure Blob logger and the existing workarounds for the async wrapper suggested by @snakefoot did not make any difference. I suspect that our logging throughput is high enough, and the write performance of the Blob Logger is slow enough, so that no matter what happens we cause the async buffer to grow, and therefore increase memory usage.

This would be fine (and expected behaviour) as long as when the site cools down the buffer eventually gets drained and memory is released. This does not appear to be happening, as although all log writes are completed, memory remains high - potential culprit is the LogEventInfo object which is reported in #2220

I did some digging and then found this fork: https://github.com/jkowalski/NLog/pull/19/files that appears to explicitly dispose of the object that may be causing all the trouble. As far as I can see, this code isn't implemented in the official NLog code base.

I've checked this Azure Blob Logger code and it appears pretty simple so I don't think the reason is this extension, besides, even if we could increase it's performance, I feel we are still masking an underlying issue with the async wrapper.

[304NotModified]

The PR (jkowalski/NLog#19) is indeed interesting. We could release a test package to check if that resolves your problem. @snakefoot what do you think?

[snakefoot]

That the PR is broken, and should not be used. Could be nice if your memory profiler could show what object chain keeps the LogEventInfo alive. Maybe there is an array that requires manual clear.

[grahambunce]

Just to update this; one thing @snakefoot suggested in #2220 helps,

batchSize="1000"

This helps in that memory increases at a much lower rate, but it's still growing.

This:

"timeToSleepBetweenBatches="0"

does not make any difference.

Here is an updated objected chain if it helps?

[snakefoot]

If you are using the AzureAppendBlob from nuget. Then you can try and configure this on the blob-target (Not the AsyncWrapper) OptimizeBufferReuse="true" It can be used on targets that are very simple (Like the blob-target). Or on smart targets like file-target (Already enabled by default)

[snakefoot]

@grahambunce Here is an updated objected chain if it helps?

I'm pretty sure that the System.Collections.Generic.Queue clears the reference after Dequeue. So it seems you have over 300.000 logevents pending waiting to get through NLog.AzureBlobStorage.

Thought your problem was that when the system was idle, then there was still a high memory pressure. Looks like you are shown the numbers of when the system is fully active? I guess your problem is caused by the string-allocations that are kept alive until being written. The garbage collector punishes you by putting the strings into GC1 and GC2, so when finally written then they are not easy to get rid of.

You could also improve the NLog.AzureBlobStorage to handle batches of logevents, instead of just writing one at a time.

NLog could also be nicer regarding the async-allocations, and delaying the string-allocation until needing the string (Just keeping a StringBuilder around).

[304NotModified]

With Queue, List, and other such data structures in the .NET Framework, when you remove an element from the collection, the collection internally wipes out its reference to the stored element,

https://blogs.msdn.microsoft.com/pfxteam/2012/05/08/concurrentqueuet-holding-on-to-a-few-dequeued-elements/

[304NotModified]

Is it the repo:

https://github.com/heemskerkerik/NLog.AzureAppendBlob

?

[grahambunce]

@snakefoot Yes, even though the system is idle, the memory dump still shows nlog objects in memory. For example, I ran a soak test to increase memory, waited 60 minutes, confirmed that nothing was being written to the logs, and then took this memory dump.

I've still got the NLog objects in memory. I would have expected the GC to kick them out by then as the site wasn't doing anything at all. I took a few other snapshots too and, surprisingly, the NLog objects were slightly different (which I find odd) but still in the same ballpark.

@304NotModified Yes, I am using that repro. There is another https://github.com/JDetmar/NLog.Extensions.AzureStorage/blob/master/src/NLog.Extensions.AzureStorage/BlobStorageTarget.cs that seems to have a more advanced NLog Target that supports this method:

protected override void Write(IList<AsyncLogEventInfo> logEvents)

I can't tell from the NLog framework how it decides to call the list overload when compared with the single overload but if as @snakefoot suggests this is a better option for performance and mitigating the issue I will try it.

I still wonder if even if I improve throughput it's still masking an underlying issue?

[snakefoot]

Made a small test program that uses the file-target to write against an non-existing path (KeepFileOpen=false, ConcurrentWrites=true).

The test program writes 1 million logevents, and reaches 1 Gigabyte in memory usage (Started from 100 Megabytes)

When I try to force GC.Collect(2) then it drops 100 MegaBytes. If I force one more then it drops 100 MegaBytes again. This continues until it reaches the starting point again of 100 MegaBytes.

Just for fun then I also tried the AsyncWrapper using the System.Collections.Concurrent.ConcurrentQueue (Works like a linked list). It had the same pattern, with the exception that it didn't leave a large array like the System.Collection.Generic.Queue.

[grahambunce]

@snakefoot thanks for creating the test. Is this agreeing or disagreeing with me? :) I guess one view is that, yes, the memory footprint increases as expected but that a forced GC will eventually drop the memory used. The other view is that, what happens if you don't force the GC?

In my case the app pool ran low on memory, requests backed up and then the site crashed... so any "auto" GC execution rules didn't pick up the problem...

[snakefoot]

so any "auto" GC execution rules didn't pick up the problem...

The GC2 usually only kicks in when there is a change in memory pressure after the previous GC2. This is to avoid the expensive GC2. But when using GC-Server/GC-Concurrent then a GC2 is not a complete swipe of the entire memory. Thus the "funny" issue that multiple forced GC2-calls will make it drop even further.

Again I'm no expert in the NET Garbage Collector, and its triggers. But yes I can reproduce your issue, and the application doesn't reduce its memory usage automatically when idle, but needs "help".

[grahambunce]

@snakefoot

yes I can reproduce your issue, and the application doesn't reduce its memory usage automatically when idle, but needs "help".

Ok. Is this something that can be looked into within NLog (i.e. why is memory not being released without help) or do you consider this a hosting app issue?

[snakefoot]

This is not an issue that can be fixed in the NLog core engine. It had to be fixed in the custom Nlog target. I guess some day in the future, there will be created a durable-wrapper, that writes directly to a json-file (instead of keeping in memory). Then reads from this json-file and only keeps those LogEvents in memory that are about to be sent to the final target (Ex. the blob).

[snakefoot]

Maybe try and use the RoundRobinGroup and have multiple blob targets inside this. Each wrapped with their own AsyncWrapper (Works best with NLog 4.5.2) <target type="RoundRobinGroup" name="superblob"> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> <target type="AsyncWrapper" timeToSleepBetweenBatches="0"> <target type="AzureAppendBlob" connectionString="logs" container="logs" /> </target> </target> See also: https://github.com/nlog/NLog/wiki/RoundRobinGroup-target