Nlog pende de traza (? Multithreading emisión)

Question

Los síntomas se cuelgan de aplicación (alojado en IIS 7) Al acoplar con debuging encontró que hay ~ 100 hilos con pilas de este tipo:

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> ... 

uno con

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> ... 

y uno con

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> ... 

Esta situación se produce alguna veces, puede ser una vez a la semana, y no tengo un escenario exacto para reproducirlo.

¿Cómo puedo solucionar esto? ¿Es un error en NLog, o tal vez algunos de mis usos incorrectos o mis configuraciones erróneas?

Answer 1

Dictionary<T> no es hilo de seguridad, por lo que para acceder a él en varios subprocesos podría dar lugar a este tipo de problemas,

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

Es difícil saber si se puede configurar Nlog para trabajar en múltiples hilos . ¿Intentó usar su AsyncWrapper?

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

según el Foro Nlog, usando manera asíncrona debería resolver el problema,

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

Answer 2

que he encontrado recientemente el mismo problema - un montón de hilos de bloqueo en WriteAsyncLogEvent. Aunque no tenía ningún hilo Dictionary. Tenía un hilo atorado en AsyncRequestQueue.Enqueue, que podría haber perdido en su lista de hilos.

En mi caso, el problema era que overflowAction en AsyncWrapper se configuró en ... Block! Configurarlo en Discard es una manera mucho más inteligente de lidiar con el registrador sobrecargado.

A veces los mensajes de registro se acumulan sin culpa de NLog. A veces, el proceso se bloquea por otros motivos (bloqueo de disco, intercambio pesado, desorden de antivirus, GC completo). La lista de hilos contiene muchos hilos pegados en NLog simplemente porque NLog pasa a depender del mismo recurso sobrecargado.