log4Net causing thread to be blocked

Question

I am using log4Net to log the activity and after analyzing the stack trace from perfmon I see there is a deadlock like scenario as shown below

    ntdll!NtWaitForMultipleObjects+a
    KERNELBASE!WaitForMultipleObjectsEx+e1
    clr!WaitForMultipleObjectsEx_SO_TOLERANT+62 
    clr!Thread::DoAppropriateWaitWorker+1e4 
    clr!Thread::DoAppropriateWait+7d 
    clr!CLREventBase::WaitEx+c4
    clr!AwareLock::EnterEpilogHelper+ca
    [[GCFrame]] 
    clr!AwareLock::EnterEpilog+62 
    clr!AwareLock::Contention+2a7f4a
    clr!JITutil_MonContention+af
    [[GCFrame]] 
    [[HelperMethodFrame] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object) 
    log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+47 
    log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a8
    log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+74 
    log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+6a
    log4net.Core.LogImpl.InfoFormat(System.String, System.Object)+cc
    Archival.Logic.Status(Archival.ProcessArgs)+240 
    Archival.Logic.Product(Archival.ProcessArgs)+221 
    Archival.Logic.Number(Archival.ProcessArgs, System.Collections.Generic.IEnumerable`1<LenderProduct>)+2e9 
    Archival.Logic+<>c__DisplayClass3_0.<ArchiveDealsPerAsset>b__1(System.String)+b5
    mscorlib_ni!System.Threading.Tasks.Parallel+<>c__DisplayClass42_0`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].<PartitionerForEachWorker>b__1()+2bd
    mscorlib_ni!System.Threading.Tasks.Task.InnerInvokeWithArg(System.Threading.Tasks.Task)+20 
    mscorlib_ni!System.Threading.Tasks.Task+<>c__DisplayClass176_0.<ExecuteSelfReplicating>b__0(System.Object)+114 
    mscorlib_ni!System.Threading.Tasks.Task.Execute()+46 
    mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+162 
    mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+14 
    mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+21c
    mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+73 
    mscorlib_ni!System.Threading.ThreadPoolWorkQueue.Dispatch()+152 
    clr!CallDescrWorkerInternal+83 
    clr!CallDescrWorkerWithHandler+4e 
    clr!MethodDescCallSite::CallTargetWorker+f8
    clr!QueueUserWorkItemManagedCallback+2a
    clr!ManagedThreadBase_DispatchInner+39 
    clr!ManagedThreadBase_DispatchMiddle+6c
    clr!ManagedThreadBase_DispatchOuter+75 
    [[DebuggerU2MCatchHandlerFrame]] 
    clr!ManagedThreadBase_FullTransitionWithAD+2f 
    clr!ManagedPerAppDomainTPCount::DispatchWorkItem+a0
    clr!ThreadpoolMgr::ExecuteWorkRequest+64 
    clr!ThreadpoolMgr::WorkerThreadStart+f5
    clr!Thread::intermediateThreadProc+86 
    kernel32!BaseThreadInitThunk+22 
    ntdll!RtlUserThreadStart+34

I init the logger

private static readonly ILog logger = LogManager.GetLogger(typeof(Program));

What can be done to avoid this scenario. I have reviewed an option to add per thread log .But, this will be an overkill as I will have 100 logs per day.

The following is the configuration for log4Net:

<log4net>
<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
  <mapping>
    <level value="ERROR"/>
    <foreColor value="White"/>
    <backColor value="Red"/>
  </mapping>
  <mapping>
    <level value="WARN"/>
    <foreColor value="White"/>
    <backColor value="Yellow"/>
  </mapping>
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%thread] - %message%newline"/>
  </layout>
  <filter type="log4net.Filter.LevelRangeFilter">
    <levelMin value="INFO"/>
  </filter>
</appender>
<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
  <file value="Logs\logfile.txt"/>
  <appendToFile value="true"/>
  <rollingStyle value="Date"/>
  <datePattern value="yyyyMMdd"/>
  <maxSizeRollBackups value="3"/>
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%thread] %-5level - %message%newline"/>
  </layout>
  <filter type="log4net.Filter.LevelRangeFilter">
    <levelMin value="INFO"/>
  </filter>
</appender>
<root>
  <level value="ALL"/>
  <appender-ref ref="ColoredConsoleAppender"/>
  <appender-ref ref="RollingLogFileAppender"/>
</root>

Sure that you are using NLog and not log4net, since log4net is part of your stacktrace? — Rolf Kristensen, Jul 21 '17 at 20:39
How fast are you logging events? Your RollingLogFileAppender is not set to use minimal locking, which should mean that the file is locked at the started of the program and not locked/unlocked for each event. So I don't think the lock you are seeing is relating to to the actual writing to the file and if that is the case, it is possible that using a different file per thread may not solve the issue. — sgmoore, Jul 24 '17 at 17:25
_"I will have 100 logs per day"_ - how are you creating all these logs? — stuartd, Jul 25 '17 at 00:50
@stuartd if we separate the log files per thread it might result in 100 log files. — user2526236, Jul 25 '17 at 14:48
@stuartd Please refer to the link : https://stackoverflow.com/questions/6956064/logging-to-an-individual-log-file-for-each-individual-thread — user2526236, Jul 25 '17 at 15:28

score 0 · Answer 1 · answered Jul 25 '17 at 09:37

0

Just a guess on what is going on, for some reason the Logs\logfile.txt is locked when you want to write to the file. A second log message will wait till the first log messages is finished (your stacktrace). Minimal locking will not help you here because you still need to lock the file. When you want to access the log file you need to copy it first and then open the copied version of the log file with the inspection tool. That way you are sure you are not blocking to process that wants to log to the logfile.

answered Jul 25 '17 at 09:37

Peter

27,590
8
64
84

Will adding a lock/monitor for each logger.InfoFormat("Message to be logged") help. Will this result in performance issues. – user2526236 Jul 25 '17 at 14:46
You will get the same raise condition if the file is locked – Peter Jul 25 '17 at 14:52
How can I solve this race around condition? any suggestions – user2526236 Jul 25 '17 at 15:00
@user2526236 if would help if you added a reproducible example. – stuartd Jul 25 '17 at 15:19
@stuartd I am not able to reproduce the issue. – user2526236 Jul 25 '17 at 15:28
You can lock the original log file on the server. When you have 2 logging messages you will probably reproduce the stacktrace. – Peter Jul 25 '17 at 15:34

log4Net causing thread to be blocked

1 Answers1