CODEWITHSUNDEEP
c#.netmultithreadingloggingnlog
pil0t
pil0t

Reputation: 2183

NLog hangs in trace (multithreading issue?)

Symptoms is hanging of application (hosted in IIS 7) When attaching with debuging found that there are ~100 threads with stacks like this:

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 some times, may be one time a week, and I don't have exac scenario to reproduce it.

How can I fix this? Is it bug in NLog, or maybe some my misuses or misconfigure?

Upvotes: 7

Views: 2416

Answers (2)

Robert Važan
Robert Važan

Reputation: 3447

I have recently encountered the same problem - lots of threads blocking on WriteAsyncLogEvent. I did not have any Dictionary threads though. I had one thread stuck in AsyncRequestQueue.Enqueue, which you might have missed in your thread list.

In my case, the problem was that overflowAction on AsyncWrapper was set to... Block! Setting it to Discard is much wiser way to deal with overloaded logger.

Sometimes the log messages accumulate for no fault of NLog itself. Sometimes the process is stuck for other reasons (disk blocking, heavy swapping, antivirus messing up, full GC). The thread list then contains lots of threads stuck on NLog simply because NLog happens to depend on the same overloaded resource.

Upvotes: 1

Lex Li
Lex Li

Reputation: 63289

Dictionary<T> is not thread safe, so accessing it in multiple threads might 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 is hard to tell whether you can configure NLog to work in multithreading. Did you try to use its AsyncWrapper?

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

According to NLog forum, using async way should resolve the problem,

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

Upvotes: 1

Related Questions