为啥 log4net 线程卡在等待中？

Posted 2023-04-12

技术标签:

【中文标题】为啥 log4net 线程卡在等待中？【英文标题】：Why are log4net threads stuck on a wait?为什么 log4net 线程卡在等待中？ 【发布时间】：2016-03-04 15:07:10 【问题描述】：

上周我们的一台测试服务器的日志驱动器上的磁盘空间不足。释放磁盘空间后，我仍然有几个线程的调用堆栈似乎卡在 log4net AppenderSkeleton.DoAppend 内部，这令人困惑，因为我期望 log4net 是线程安全的。

在看到线程被卡住时，我是否正确读取堆栈？堆栈是否指示线程卡在“lock(this)”或其他地方？我的猜测是在其他地方，因为我希望看到类似 Monitor.Enter 的内容，如果它卡在 lock(this) 上。其中一个线程似乎显示 DoAppend 在滚动到新文件的过程中。是不是所有的 DoAppend 线程在创建这个文件时都被阻塞了？但是，我希望这些线程在我们释放磁盘空间后会变得畅通。

感谢任何帮助理解为什么 log4net 似乎卡在这么多线程上。

这是一个调用堆栈示例，显示了在 DoAppend 内部等待时阻塞的线程：

ntdll.dll!_NtWaitForMultipleObjects@20() + 0x15 字节 ntdll.dll!_NtWaitForMultipleObjects@20() + 0x15 字节 KERNELBASE.dll!_WaitForMultipleObjectsEx@20() + 0x36 字节 kernel32.dll!_WaitForMultipleObjectsExImplementation@20() + 0x8e 字节 [托管到本地转换] log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0x3e 字节 log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

这里是来自 log4net AppenderSkeleton.DoAppend 的来源

public void DoAppend(LoggingEvent loggingEvent) 

    // This lock is absolutely critical for correct formatting
    // of the message in a multi-threaded environment.  Without
    // this, the message may be broken up into elements from
    // multiple thread contexts (like get the wrong thread ID).

    lock(this)
    
        if (m_closed)
        
            ErrorHandler.Error("Attempted to append to closed appender named ["+m_name+"].");
            return;
        

        // prevent re-entry
        if (m_recursiveGuard)
        
            return;
        

        try
        
            m_recursiveGuard = true;

            if (FilterEvent(loggingEvent) && PreAppendCheck())
            
                this.Append(loggingEvent);
            
        
        catch(Exception ex)
        
            ErrorHandler.Error("Failed in DoAppend", ex);
        
#if !MONO && !NET_2_0
        // on .NET 2.0 (and higher) and Mono (all profiles), 
        // exceptions that do not derive from System.Exception will be
        // wrapped in a RuntimeWrappedException by the runtime, and as
        // such will be catched by the catch clause above
        catch
        
            // Catch handler for non System.Exception types
            ErrorHandler.Error("Failed in DoAppend (unknown exception)");
        
#endif
        finally
        
            m_recursiveGuard = false;

这是我的 log4net 设置：

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>
  <log4net xsi:noNamespaceSchemaLocation="log4net.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="g:\logfiles\mySerivceName\" />
      <appendToFile value="true" />
      <rollingStyle value="Date" />
      <datePattern value="'myServiceName.'yyyy-MM-dd-HH'-00.log'"/>
      <staticLogFileName value="false" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%dateyyyy-MM-dd HH:mm:ss.fff %-5level [%3thread] [%-50.50stacktrace] %message %newline"/>
      </layout>
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="INFO" />
        <levelMax value="FATAL" />
      </filter>
    </appender>
    <appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
        <to value="alerts@myCompanyName.com" />
        <from value="servicename@localnetwork" />
        <subject value="$COMPUTERNAME - Error Generated" />
        <smtpHost value="mySmtpServerIpAddress" />
        <bufferSize value="2" />
        <lossy value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%dateyyyy-MM-dd HH:mm:ss.fff %-5level [%3thread] [%-50.50stacktrace] %message %newline" />
        </layout>
        <filter type="log4net.Filter.LevelRangeFilter">
            <levelMin value="ERROR" />
            <levelMax value="FATAL" />
        </filter>
    </appender>
    <root>
      <level value="DEBUG"/>
      <appender-ref ref="RollingFileAppender" />
    </root>
  </log4net>
</configuration>

滚动到新文件的 DoAppend 堆栈

mscorlib.dll!System.Text.StringBuilder.Append(char value) Line 953 + 0xb bytes
  mscorlib.dll!System.IO.PathHelper.Append(char value) Line 139 + 0x18 bytes
  mscorlib.dll!System.IO.Path.NormalizePath(string path, bool fullCheck, int maxPathLength, bool expandShortPaths) Line 620
  mscorlib.dll!System.IO.Path.GetDirectoryName(string path) Line 170 + 0x24 bytes
  log4net.dll!log4net.Appender.FileAppender.LockingModelBase.CreateStream(string filename, bool append, System.IO.FileShare fileShare) + 0x35 bytes     
  log4net.dll!log4net.Appender.FileAppender.ExclusiveLock.OpenFile(string filename, bool append, System.Text.Encoding encoding) + 0x2d bytes      
  log4net.dll!log4net.Appender.FileAppender.OpenFile(string fileName, bool append) + 0x1ac bytes  
  log4net.dll!log4net.Appender.RollingFileAppender.OpenFile(string fileName, bool append) + 0x189 bytes 
  log4net.dll!log4net.Appender.FileAppender.SafeOpenFile(string fileName, bool append) + 0x2d bytes     
  log4net.dll!log4net.Appender.FileAppender.PrepareWriter() + 0x13 bytes  
  log4net.dll!log4net.Appender.TextWriterAppender.PreAppendCheck() + 0x32 bytes 
  log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0xe0 bytes 
  log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes      
  log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

这是同一台机器上的另一个调用堆栈，不同的进程，也挂了：

clr.dll!AwareLock::Contention() + 0x10d 字节 [托管到本地转换] log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0x3e 字节 log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

在同一台机器上的第二个进程中，还有一个线程似乎被阻止试图翻转。

MSVCR120_CLR0400.dll!_memcpy() + 0x21e 字节 [托管到本地转换] mscorlib.dll!System.Buffer._Memcpy(byte* dest, byte* src, int len) 第 484 行 + 0x20 字节 C# mscorlib.dll!System.Buffer.Memcpy(byte* dest, byte* src, int len) 第 401 行 C# mscorlib.dll!string.FillStringChecked(string dest, int destPos, string src) 第 1523 行 + 0xf 字节 C# mscorlib.dll!string.ConcatArray(string[] values, int totalLength) 第 3340 行 C# mscorlib.dll!string.Concat(object[] args) 第 3180 行 + 0xa 字节 C# log4net.dll!log4net.Appender.FileAppender.OpenFile(string fileName, bool append) + 0x162 bytes log4net.dll!log4net.Appender.RollingFileAppender.OpenFile(string fileName, bool append) + 0x189 bytes log4net.dll!log4net.Appender.FileAppender.SafeOpenFile(string fileName, bool append) + 0x2d bytes log4net.dll!log4net.Appender.FileAppender.PrepareWriter() + 0x13 字节 log4net.dll!log4net.Appender.TextWriterAppender.PreAppendCheck() + 0x32 字节 log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0xe0 字节 log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 字节 log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

【问题讨论】：

所以你是说这些错误来自 CLR 和内核？如果这是真的，我同意你的看法。但是调用堆栈的哪一部分让您得出了这个结论？好吧，调用堆栈向我们展示了我们这里有一个死锁。应用程序崩溃了还是仍在运行？ lock 不会自行超时，因此它被卡在某个尝试写入文件的地方，但由于磁盘空间不足而失败。某些线程冻结。该应用程序的各个方面仍然响应迅速。但是依赖于阻塞线程的部分永远不会恢复。最终不得不重启服务器。我也相信 log4net 发生了死锁。只是不认为这是可能的。我也在 DoAppend 中遇到了死锁。我的是由于我拦截了跟踪消息，但我仍然不完全明白为什么。你的代码是什么样的？有什么更新吗，伙计们？ 【参考方案1】：

我在堆栈溢出时多次看到 log4net 的这种行为。当您用完磁盘空间时，fileappender 似乎开始阻塞。我猜这是附加程序中的一个错误，因此将其记录为错误似乎适合这种情况。

【讨论】：

以上是关于为啥 log4net 线程卡在等待中？的主要内容，如果未能解决你的问题，请参考以下文章

Log4Net组件的应用详解

C#Log4net记录日志（转）

MVC5中使用Log4Net

log4net managedcoloredconsole 不适用于动态创建

Log4Net 正在创建文件但未写入文件

Vagrant 卡在“等待 VM 启动”