NLog: Threads deadlocking with AsyncWrapper

NLog version: 4.6.4

Platform: .NET Core 2.2.7 Linux

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

let configureLogging (logLevel: LogLevel) =
    LayoutRenderer.Register<HostSiteLayoutRenderer>("host-site");
    LayoutRenderer.Register<CorrelationLayoutRenderer>("corr");
    let hostSite = Environment.getEnvironmentVariable "HostSite" (Some "local")
    let logLayoutString = sprintf "${longdate}|${level:uppercase=true}|${logger}|${host-site:%s}${corr}|${message}" hostSite
    let config = new LoggingConfiguration()
    let cLayout = Layout.FromString(logLayoutString);
    let consoleTarget = new ConsoleTarget( Name = "logToConsole", Layout = cLayout)
    let bufferedTarget = new Targets.Wrappers.AsyncTargetWrapper(consoleTarget, 10000, Wrappers.AsyncTargetWrapperOverflowAction.Block)
    config.LoggingRules.Add(new LoggingRule("*", logLevel, bufferedTarget))
    LogManager.Configuration <- config

During a soak test we discovered that at a certain threshold memory would climb for some processes and OOM.

oom

I was able to create a coredump of the process. Upon inspection there were over 1100 blocked threads. I dumped the stack for these and found the following:

00007F85D2FFA3A0 00007f86746a09f3 [HelperMethodFrame_1OBJ: 00007f85d2ffa3a0] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
00007F85D2FFA4D0 00007F85FE7F08B0 NLog.Targets.Wrappers.ConcurrentRequestQueue.WaitForBelowRequestLimit()
00007F85D2FFA500 00007F85FCF5B2AF NLog.Targets.Wrappers.ConcurrentRequestQueue.Enqueue(NLog.Common.AsyncLogEventInfo)
00007F85D2FFA570 00007F85FCF55E96 NLog.Targets.Wrappers.AsyncTargetWrapper.Write(NLog.Common.AsyncLogEventInfo)
00007F85D2FFA5B0 00007F85FCF55DC2 NLog.Targets.Wrappers.AsyncTargetWrapper.WriteAsyncThreadSafe(NLog.Common.AsyncLogEventInfo)
00007F85D2FFA5F0 00007F85FCF559C5 NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo)
00007F85D2FFA660 00007F85FCF5537E NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Targets.Target, NLog.Filters.FilterResult, NLog.LogEventInfo, NLog.Common.AsyncContinuation)
00007F85D2FFA690 00007F85FCF54AFC NLog.LoggerImpl.Write(System.Type, NLog.Internal.TargetWithFilterChain, NLog.LogEventInfo, NLog.LogFactory)
...
...
...

We suspected it may be an issue with the ConcurrentRequestQueue and we changed our configuration to the following

let configureLogging (logLevel: LogLevel) =
    LayoutRenderer.Register<HostSiteLayoutRenderer>("host-site");
    LayoutRenderer.Register<CorrelationLayoutRenderer>("corr");
    let hostSite = Environment.getEnvironmentVariable "HostSite" (Some "local")
    let logLayoutString = sprintf "${longdate}|${level:uppercase=true}|${logger}|${host-site:%s}${corr}|${message}" hostSite
    let config = new LoggingConfiguration()
    let cLayout = Layout.FromString(logLayoutString);
    let consoleTarget = new ConsoleTarget( Name = "logToConsole", Layout = cLayout)
    let bufferedTarget = new Targets.Wrappers.AsyncTargetWrapper(consoleTarget, 200, Wrappers.AsyncTargetWrapperOverflowAction.Block)
    bufferedTarget.ForceLockingQueue <- true
    config.LoggingRules.Add(new LoggingRule("*", logLevel, bufferedTarget))
    LogManager.Configuration <- config

When we did another soak test we found the issue to have resolved.

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Comments: 27 (17 by maintainers)

Most upvoted comments

I think this can be closed, we havent seen this pop back up after having enabled buffered writes. Thanks for all the help and hard work!

Created PR #3636 with a unit-test and and a fix for the above scenario.

Have created PR #3635 where more love and care is implemented for the Console-Target.

Also introduces a new parameter WriteBuffer=true that will reduce memory-allocations and improve speed when wrapped using AsyncWrapper.

@taion809 And you are completely sure it is NLog 4.6.4 that is deployed (and not an earlier version) ?

Anyway created #3622 that removes any attempts in being smart. Consumer-thread now always pulses producers (And not just when being busy).

When NLog 4.6.8 is released, then I would be really happy if you could try this version with ForceLockingQueue=false. There are already pre-release nuget-packages ready here (See NLog.4.6.7.10625-PR3622.nupkg):

https://ci.appveyor.com/project/nlog/nlog/builds/28056047/artifacts