2

Closed

Livelock in LogEventInfo

description

After we upgraded to NLog 2.0 we experience 100% CPU utilization and missing logs in production systems almost everyday, until application restart.

Stacktraces from a frozen system follow:

OS Thread Id: 0xd44 (27)
Child-SP RetAddr Call Site
000000000a8aeb40 000007fef2ffd544 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon)
000000000a8aebb0 000007ff00d175d2 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].TryGetValue(System.__Canon, System.__Canon ByRef)
000000000a8aebf0 000007ff00d172f2 NLog.LogEventInfo.TryGetCachedLayoutValue(NLog.Layouts.Layout, System.String ByRef)
000000000a8aec20 000007ff00d17924 NLog.Layouts.SimpleLayout.GetFormattedMessage(NLog.LogEventInfo)
000000000a8aecc0 000007ff00d16b2b NLog.Targets.FileTarget.GetBytesToWrite(NLog.LogEventInfo)
000000000a8aecf0 000007ff00d166bd NLog.Targets.FileTarget.Write(NLog.Common.AsyncLogEventInfo[])
000000000a8aee60 000007ff00d15d52 NLog.Targets.Target.WriteAsyncLogEvents(NLog.Common.AsyncLogEventInfo[])
000000000a8aef80 000007fef2fe2bbb NLog.Targets.Wrappers.AsyncTargetWrapper.ProcessPendingEvents(System.Object)
000000000a8af010 000007fef303eb96 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000000a8af060 000007fef3e90542 System.Threading._TimerCallback.PerformTimerCallback(System.Object)

OS Thread Id: 0x8c4 (28)
Child-SP RetAddr Call Site
000000000902e890 000007fef2fee6bc System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Insert(System.__Canon, System.__Canon, Boolean)
000000000902e920 000007ff00d17790 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].set_Item(System.__Canon, System.__Canon)
000000000902e950 000007ff00d1740f NLog.LogEventInfo.AddCachedLayoutValue(NLog.Layouts.Layout, System.String)
000000000902e9a0 000007ff00d171ed NLog.Layouts.SimpleLayout.GetFormattedMessage(NLog.LogEventInfo)
000000000902ea40 000007ff00d16e4b NLog.Targets.FileTarget.<Write>b__0(NLog.Common.AsyncLogEventInfo)
000000000902ea70 000007ff00d16969 NLog.Internal.SortHelpers.BucketSort[[NLog.Common.AsyncLogEventInfo, NLog],[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<NLog.Common.AsyncLogEventInfo>, KeySelector`2<NLog.Common.AsyncLogEventInfo,System.__Canon>)
000000000902eb50 000007ff00d166bd NLog.Targets.FileTarget.Write(NLog.Common.AsyncLogEventInfo[])
000000000902ecc0 000007ff00d15d52 NLog.Targets.Target.WriteAsyncLogEvents(NLog.Common.AsyncLogEventInfo[])
000000000902ede0 000007fef2fe2bbb NLog.Targets.Wrappers.AsyncTargetWrapper.ProcessPendingEvents(System.Object)
000000000902ee70 000007fef303eb96 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000000902eec0 000007fef3e90542 System.Threading._TimerCallback.PerformTimerCallback(System.Object)

Closed Jan 25 at 12:40 AM by jkowalski


comments

jkowalski wrote Jan 25 at 12:39 AM

Fixed, thank you.

pfusik wrote Jan 24 at 3:38 PM

See the attached patch, from my fork on github (pfusik).