NLog freezes in trace (multithreading problem?)

Question

Symptoms are application freezes (hosted in IIS 7). When connecting using debugging, it was found that there are ~ 100 threads with the following stacks:

NLog.dll!NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo logEvent) + 0x54 bytes NLog.dll!NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain targetListHead, NLog.LogEventInfo logEvent, NLog.Common.AsyncContinuation onException) + 0x8b bytes NLog.dll!NLog.LoggerImpl.Write(System.Type loggerType, NLog.Internal.TargetWithFilterChain targets, NLog.LogEventInfo logEvent, NLog.LogFactory factory) + 0xee bytes NLog.dll!NLog.Logger.WriteToTargets(NLog.LogLevel level, string message, object[] args) + 0x14 bytes NLog.dll!NLog.Logger.Trace<System.__Canon,long>(string message, System.__Canon argument1, long argument2) + 0x90 bytes ... <my app code> ... 

one with

 mscorlib.dll!System.Collections.Generic.Dictionary<NLog.Layouts.Layout,string>.FindEntry(NLog.Layouts.Layout key) + 0xd0 bytes mscorlib.dll!System.Collections.Generic.Dictionary<System.__Canon,System.__Canon>.TryGetValue(System.__Canon key, out System.__Canon value) + 0x14 bytes NLog.dll!NLog.Layouts.SimpleLayout.GetFormattedMessage(NLog.LogEventInfo logEvent) + 0x81 bytes NLog.dll!NLog.Targets.FileTarget.GetBytesToWrite(NLog.LogEventInfo logEvent) + 0x1c bytes NLog.dll!NLog.Targets.FileTarget.Write(NLog.Common.AsyncLogEventInfo[] logEvents) + 0x308 bytes NLog.dll!NLog.Targets.Target.WriteAsyncLogEvents(NLog.Common.AsyncLogEventInfo[] logEvents) + 0x258 bytes NLog.dll!NLog.Targets.Wrappers.AsyncTargetWrapper.ProcessPendingEvents(object state) + 0x1e6 bytes mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool ignoreSyncCtx) + 0xdc bytes mscorlib.dll!System.Threading._TimerCallback.PerformTimerCallback(object state) + 0x97 bytes ... <my app code> ... 

and one with

 mscorlib.dll!System.Collections.Generic.Dictionary<NLog.Layouts.Layout,string>.Insert(NLog.Layouts.Layout key, string value, bool add) + 0x1e0 bytes NLog.dll!NLog.LogEventInfo.AddCachedLayoutValue(NLog.Layouts.Layout layout, string value) + 0x6c bytes NLog.dll!NLog.Layouts.Log4JXmlEventLayout.GetFormattedMessage(NLog.LogEventInfo logEvent) + 0xf5 bytes NLog.dll!NLog.Targets.Target.PrecalculateVolatileLayouts(NLog.LogEventInfo logEvent) + 0xb8 bytes NLog.dll!NLog.Targets.Wrappers.AsyncTargetWrapper.Write(NLog.Common.AsyncLogEventInfo logEvent) + 0x23 bytes NLog.dll!NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo logEvent) + 0x151 bytes NLog.dll!NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain targetListHead, NLog.LogEventInfo logEvent, NLog.Common.AsyncContinuation onException) + 0x8b bytes NLog.dll!NLog.LoggerImpl.Write(System.Type loggerType, NLog.Internal.TargetWithFilterChain targets, NLog.LogEventInfo logEvent, NLog.LogFactory factory) + 0xee bytes NLog.dll!NLog.Logger.WriteToTargets(NLog.LogLevel level, string message, object[] args) + 0x14 bytes NLog.dll!NLog.Logger.Debug<Werp.Controller.Common.Interfaces.EntityEventAction,System.__Canon>(string message, Werp.Controller.Common.Interfaces.EntityEventAction argument1, System.__Canon argument2) + 0x8d bytes ... <my app code> ... 

This situation occurs several times, maybe once a week, and I don't have an exac script to play it.

How can i fix this? Is this a mistake in NLog, or maybe some of my abuse or misconfiguration?

Answer 1

Dictionary<T> not thread safe, so accessing it in multiple threads can lead to such problems,

http://msdn.microsoft.com/en-us/library/xfhwa508.aspx

http://blogs.msdn.com/b/asiatech/archive/2009/05/11/100-cpu-caused-by-system-collections-generic-dictionary.aspx

It's hard to say whether NLog can be configured to work in multithreading. Have you tried to use its AsyncWrapper?

http://nlog-project.org/wiki/AsyncWrapper_target

According to the NLog forum, using the async method should solve the problem,

http://nlog-forum.1685105.n2.nabble.com/Multi-Threading-in-NLog-td3728834.html

Answer 2

I recently ran into the same problem - lots of thread locks on WriteAsyncLogEvent . However, I did not have Dictionary threads. I had one thread stuck in AsyncRequestQueue.Enqueue that might have missed in your thread list.

In my case, the problem was that an overflowAction on AsyncWrapper was installed ... Block ! Installing it on Discard is a much wiser way to deal with an overloaded recorder.

Sometimes log messages are accumulated without errors by NLog itself. Sometimes the process gets stuck for other reasons (disk blocking, intensive swap, antivirus attack, full GC). The thread list then contains many threads stuck in NLog, simply because NLog depends on the same overloaded resource.