Nlog: Excessive locking in Target.PrecalculateVolatileLayoutsWithLock

[zvolkov]

Hi, we are on NLog 4.7.2 on .net core 3.1. We were profiling our asp.net app for some other issues and noticed that NLog's Target creates a lot of thread contention at PrecalculateVolatileLayoutsWithLock method when our apps runs under high load.

When we log we do our own formatting, so we never pass params to NLog, but we do populate the event context properties with quite a few items. We log to the async wrapper on top of the file target. Our layouts are pretty basic.

Can you give us some directions on where we should start looking in order to diagnose this. Why is PrecalculateVolatileLayoutsWithLock called a lot, to begin with. Why not its concurrent sibling? What co we do to optimize this?

Thanks a lot!

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[snakefoot]

@zvolkov PrecalculateVolatileLayoutsWithLock is activated when using LayoutRenders not marked with [ThreadSafe]-attribute.

Maybe you can show your NLog-config ?

[repo-ranger[bot]]

Please add the requested info, so we could help you better! (This issue will be closed in 7 days)

[zvolkov]

nlog.config:

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true" throwExceptions="false">
    <targets>
        <target xsi:type="AsyncWrapper" name="logfile"
                batchSize="2000" timeToSleepBetweenBatches="100" queueLimit="20000" overflowAction="grow">
            <target name="applogjson" xsi:type="File"
                    fileName="${environment:variable=XYZ_APPLOGS}/${shortdate}.applogjson">
                <layout xsi:type="JsonLayout">
                    <attribute name="timestamp" layout="${date:universalTime=false:format=yyyy-MM-ddTHH\:mm\:ss.FFFFFFFK}" />
                    <attribute name="sequenceNumber" layout="${event-context:item=SequenceNumber}" />
                    <attribute name="level" layout="${level:upperCase=true}" />
                    <attribute name="saneId" layout="${event-context:item=SaneId}" />
                    <attribute name="traceId" layout="${event-context:item=TraceId}" />
                    <attribute name="requestId" layout="${event-context:item=RequestId}" />
                    <attribute name="logger" layout="${logger}" />
                    <attribute name="logId" layout="${event-context:item=LogId}" />
                    <attribute name="message" layout="${message}" />

                    <!-- stateful application -->
                    <attribute name="sessionId" layout="${event-context:item=SessionId}" />
                    <attribute name="rootContext" layout="${event-context:item=RootContextId}" />
                </layout>
            </target>
        </target>
    </targets>

    <include file="${environment:variable=XYZ_APPROOT}/Config/nlog-override-local.config" ignoreErrors="true" />

    <rules>
        <!-- microsoft -->
        <logger name="Microsoft.*"
            minlevel="Error" writeTo="logfile" final="true" />

        <!-- default logging level for everything. overriden by specific rules above. -->
        <logger name="*"
            minlevel="Info" writeTo="logfile" final="true" />
    </rules>
</nlog>

nlog-override-local.config:

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <targets>
        <target xsi:type="AsyncWrapper" name="file" batchSize="2000" timeToSleepBetweenBatches="100" queueLimit="20000" overflowAction="grow">
            <target name="flatText" xsi:type="File"
                layout="${time} [${pad:padding=-5:inner=${level:uppercase=true}}] [R:${pad:padding=36:inner=${event-context:item=RequestId}}] ${logger}: ${message} ${exception:format=toString:maxInnerExceptionLevel=100}"
                fileName="${environment:variable=XYZ_APPLOGS}/${environment:variable=XYZ_DEPLOYMENT}-${shortdate}.log" />
        </target>
    </targets>
    <rules>
        <logger name="*" minlevel="Info" writeTo="file" final="true" />
    </rules>
</nlog>

[zvolkov]

We used to have thread id layout renderer there, which is not ThreadAsync. Removing it seemed to make things better (I think? not really sure as there is a lot of variation from one test run to another) - but even without the thread id, I still see a lot of waiting on that specific lock whenever I saturate the system in my load-tests. By "a lot" I mean one minute of waiting (summed up across ~100 threads) per one minute of load-test running.

[snakefoot]

The problem is the use of the obsolete ${event-context}. Make a search of ${event-context and replace with ${event-properties (Remember to also to fix nlog-override-local.config)

Other recommendations:

• Remove timeToSleepBetweenBatches="100". The default value of 1 is faster.
• Remove batchSize="2000". The default value of 200 is faster.
• Update all use of ${environment:variable with the option cached=true". Ex: ${environment:variable=XYZ_APPLOGS:cached=true}

 - If it is important to react to changes of environment-variables. Then use the option `cachedSeconds=30`. Ex: `${environment:variable=XYZ_APPLOGS:cachedSeconds=30}`

[zvolkov]

Perfect, thanks a ton! We will apply these and come back only if we still have issues at that point. This was super helpful.

[snakefoot]

Another thing to consider is configure the file-target to use keepFileOpen="true" and concurrentWrites="false":

<target name="applogjson" xsi:type="File" keepFileOpen="true" concurrentWrites="false"
                    fileName="${environment:variable=XYZ_APPLOGS}/${shortdate}.applogjson">

Same can be considered for <target name="flatText" xsi:type="File". Opening and closing the file for every write-operation hurts performance. But if multiple applications are writing to the same files, or the files are placed on a network-drive, then it might not be a good idea to change these setting.s

[zvolkov]

Thanks a lot, will do.

[zvolkov]

@snakefoot looks like that caching option is not ThreadSafe and so it reintroduces the calls to PrecalculateVolatileLayoutsWithLock. Other than that the rest of your suggestions worked great.

[snakefoot]

@zvolkov Thank you for the feedback. Guess some effort should be investigated in making cached-attribute work with full concurrency (Little unexpected that a setting for optimization actually gives a performance hit).

[snakefoot]

Created PR #4132 to add [ThreadSafe]-attribute to CachedLayoutRendererWrapper.

[snakefoot]

NLog 4.7.6 has been released, where cached=true does not hurt thread-concurrency:

https://www.nuget.org/packages/NLog/4.7.6/