NLog async attribute strange behaviour

[Nail Salikhov]

I try to test NLog performance (latest version) with with settings:

<?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" autoReload="true">
    <variable name="basePath" value="c:\logs\" />
    <variable name="msgFormat" value="${message}" />
    <targets async="true">
        <target name="file"
                xsi:type="File"
                fileName="${basePath}/${logger}/${date:format=yyyy}/${date:format=MMMM}/log-${date:format=yyMMdd}-${level}.log"
                layout="${msgFormat}"
                concurrentWrites="true" />
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="file"/>
    </rules>
</nlog>

and run this code:

var msg = "this is example string for logging test. it's not very long, but not very short";
var count = 20000;
Parallel.For(0, count, x => nlog.Info(msg));

NLog writes to file, but when file size reaches 1MB it stops writing. I try to use simple for loop, but it doesn't helped me. And i try to use internal logging, but there is no errors, by the way i see there this strings:

2013-04-01 11:36:18.2458 Trace Opening c:\logs/NLogTest/2013/April/log-130401-Info.log with concurrentWrite=False

It's very strange, because concurrentWrites default value is true, furthermore i've set this value in config.

Also, if i remove async attribute or use AsyncWrapper target instead, everything is gonna be ok, but writing speed drops significantly.

[Kim Christensen]

Hi,

I'll have to look into this.
When you removed the async attribute, and added the wrapper instead, did you also change the rule to log using the wrapper? Just trying to figure out the performance drop when using the wrapper.

[Nail Salikhov]

Hm, i didn't any changes in rules section. I should? In FAQ i dont see anything about it.

понедельник, 1 апреля 2013 г., 13:39:35 UTC+4 пользователь Kim Christensen написал:

[Kim Christensen]

When you are using the async attribute you don't have to change anything, but when you are a wrapper manually, you have to write to the wrapper instead.

[Nail Salikhov]

Oh, i understand that, thank you! )

I fixed case with AsyncWrapper — now it's behaviour is the same as with async attribute — when file gets 1MB size, it stops appending to it.

[Kim Christensen]

Okay that I would expect. I'll look into the problem later today, and hopefully figure out why it happens.

[Nail Salikhov]

Thank you. I will waiting for your feedback.

[Kim Christensen]

The problem lies in the default value of the AsyncWrappers QueueLimit, which is 10000.

The value determines how big the queue of messages to write are allowed to be, the problem arises because all 20000 messages are queued before anything is written to the file, which causes NLog to discard the last 10000 messages.

Unfortunately this cannot be changed when using the async attribute, you have to define the AsyncWrapper manually to be able to control the QueueLimit, which is done like this:

<?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" autoReload="true">
    <variable name="basePath" value="c:\logs\" />
    <variable name="msgFormat" value="${message}" />
    <targets async>

        <target name="asyncWrapper" xsi:Type="AsyncWrapper" queueLimit="20000">

            <target name="file"
                xsi:type="File"
                fileName="${basePath}/${logger}/${date:format=yyyy}/${date:format=MMMM}/log-${date:format=yyMMdd}-${level}.log"
                layout="${msgFormat}"
                concurrentWrites="true" />
       </target>
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="file"/>
    </rules>
</nlog>

Where QueueLimit is set to 20000.

[Kim Christensen]

I've also answered the question on StackOverflow

[Kim Christensen]

You could also changed the OverflowAction if you need to do something other the discard messages not put in the queue, see AsyncWrapper documentation for more information. The options are Block, Discard or Grow.

Den mandag den 1. april 2013 13.00.01 UTC+2 skrev Nail Salikhov:

[Nail Salikhov]

Kim, thank you!

I will use OverflowAction = "grow" — it very nice solution, because NLog processed queue. 

I set your answer as solution in StackOverflow. Thanks again!

[Nail Salikhov]

fix: it very nice solution, because NLog processed queue very fast.