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.
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)
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 (SeeNLog.4.6.7.10625-PR3622.nupkg
):https://ci.appveyor.com/project/nlog/nlog/builds/28056047/artifacts