NLog devours memory and doesn't release it back

[Dennis-Petrov]

Hi.

Bug

For testing purposes my application is running as a console application.

I've faced with high memory consumption on a testing machine (about 3 GB memory per process). Here's process dump analysis results from VS 2017 (top of roots):

As you can see, first 7 items are NLog ones with about 2 GB of memory.

Logging is used very intensive, and I don't want to loose log items, that's why overflowAction="Grow" is set below.

What am I doing wrong? Is this actually a bug? Is configuration below valid?

NLog version: 4.4.12

Platform: .Net 4.6.2

Current NLog config:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off"
      internalLogFile="${specialfolder:folder=CommonApplicationData}/Terralink xDE/Logs/nlog-internal.log">

    <targets>
        <target name="ImConsoleLog" xsi:type="Console">
            <layout xsi:type="CsvLayout" delimiter="Tab" withHeader="false">
                <column name="date" layout="${date}" />
                <column name="level" layout="${level:upperCase=true}" />
                <column name="Message" layout="${event-properties:item=Message}" />
                <column name="exception" layout="${exception:format=ToString}" />
            </layout>
        </target>

        <target name="AsyncFileLog" xsi:type="AsyncWrapper" overflowAction="Grow">
            <target name="FileLog" xsi:type="File" encoding="UTF-8" fileName="${specialfolder:folder=CommonApplicationData}/Terralink xDE/Logs/${event-properties:item=OperatorId}/${event-properties:item=BoxId}/${logger}/${logger}-${date:format=dd.MM.yyyy} ${date:format=HH}-00.log">
                <layout xsi:type="CsvLayout" delimiter="Tab" withHeader="false">
                    <column name="date" layout="${date}" />
                    <column name="level" layout="${level:upperCase=true}" />
                    <column name="processname" layout="${processname}" />
                    <column name="threadid" layout="${threadid}" />
                    <column name="OperatorId" layout="OperatorId: ${event-properties:item=OperatorId}" />
                    <column name="BoxId" layout="BoxId: ${event-properties:item=BoxId}" />
                    <column name="PackageId" layout="PackageId: ${event-properties:item=PackageId}" />
                    <column name="DocumentId" layout="DocumentId: ${event-properties:item=DocumentId}" />
                    <column name="DocumentEventId" layout="DocumentEventId: ${event-properties:item=DocumentEventId}" />
                    <column name="Message" layout="Message: ${event-properties:item=Message}" />
                    <column name="exception" layout="${exception:format=ToString}" />
                </layout>
            </target>
        </target>
    </targets>

    <rules>
        <logger name="IM" writeTo="ImConsoleLog" minlevel="Debug"/>
        <logger name="*" writeTo="AsyncFileLog" />
    </rules>
</nlog>

[304NotModified]

Well grow is keeping all logs in memory. Another option is too write synchronous.

You could also try to write faster, e.g. timeToSleepBetweenBatches=0 and batchSize=1000, see https://github.com/nlog/nlog/wiki/AsyncWrapper-target#parameters

2 GB sounds indeed too much, but it really depends on how many logs you're writing.

[Dennis-Petrov]

Well grow is keeping all logs in memory

Just to keep things clear.

As far as I understand, AsyncWrapper uses internal in-memory buffer for pending log items, and grow means "when there's no enough space in buffer, increase it".

But when particular item is sent to underlying target (FileLog in my case), it must be thrown away, isn't it?

I mean, there's no reason to keep written item in memory any more.

You could also try to write faster

Thanks, I'll try to set these values.

Synchronous logging isn't a good choice for me - this application is a backend service, and it write logs intensively.

[304NotModified]

As far as I understand, AsyncWrapper uses internal in-memory buffer for pending log items, and grow means "when there's no enough space in buffer, increase it".

But when particular item is sent to underlying target (FileLog in my case), it must be thrown away, isn't it?

yes indeed!

[Dennis-Petrov]

OK. So, the only reason I see at the moment is that log items are being produced faster, than background thread writes them to file. I really should try to re-configure async wrapper.

Thanks. I'll close the issue.

[304NotModified]

OK thanks for the feedback!

[snakefoot]

@Dennis-Petrov You are waiting for this commit, that fixes the default behavior of the async-wrapper. #1757

Right now you have to configure the Async-wrapper manually. But you should also check the configuration of the file-target. NLog uses the most compatible file-access by default, but keepFileOpen="false" only allows for 1500 writes/sec, but the asyncwrapper helps batching multiple logevents into a single write.

If you don't have multiple processes writing to the same file, then you should configure these settings for the file-target:

keepFileOpen="true" concurrentWrites="false"

If you need multiple AppDomains/Processes writing to the same file (and it is not on a network-drive), then you should use this file-target configuration (enables atomic file access between processes on the same machine)

keepFileOpen="true" concurrentWrites="true"

If you must use the most compatible file-access, then you should add this to your file-target configuration (This is no longer needed after #3444 in NLog 4.6.5, as it chooses optimal size)

bufferSize="4096"

See also https://github.com/nlog/NLog/wiki/File-target#performance-tuning-options

[Dennis-Petrov]

@snakefoot, thanks a lot!
I'm updating NLog configuration.