c# - log4net BufferingForwardingAppender 性能问题

Question

编辑 2:我已经解决了这个问题(见下面的答案)请注意，这个问题可能会影响所有装饰有 BufferingForwardingAppender 的附加程序以及所有继承自 BufferingAppenderSkeleton 的附加程序(分别为:AdoNetAppender、RemotingAppender、SmtpAppender 和 SmtpPickupDirAppender) *

我正在做一些非常基本的 log4net 工作台，我尝试用 BufferingForwardingAppender 装饰 RollingFileAppender。

我在通过 BufferingForwardingAppender 而不是直接通过 RollingFileAppender 时遇到了糟糕的性能，我真的不明白原因。

这是我的配置:

<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
  <file value="c:\" />
  <appendToFile value="false" />
  <rollingStyle value="Composite" />
  <datePattern value="'.'MMdd-HH'.log'" />
  <maxSizeRollBackups value="168" />
  <staticLogFileName value="false" />
  <layout type="log4net.Layout.PatternLayout">      
    <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
  </layout>
</appender>

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
</appender>

<root>
  <level value="DEBUG" />
  <appender-ref ref="BufferingForwardingAppender" />    
</root>

这是基准(非常简单的代码):

var stopWatch = new Stopwatch();
stopWatch.Start();            
for (int i = 0; i < 100000; i++)            
{
   Log.Debug("Hello");
}
stopWatch.Stop();
Console.WriteLine("Done in {0} ms", stopWatch.ElapsedMilliseconds);

直接通过 RollingFileAppender 输出是:

Done in 511 ms

在通过 BufferingForwardingAppender 装饰 RollingFileAppender 时:

Done in 14261 ms

这大约慢了 30 倍。

我以为我可以通过在将日志写入文件之前缓冲一定数量的日志来提高速度，但是由于某种原因，它会让事情变得更糟。

在我看来配置没问题，所以这真的很奇怪。

有人知道吗？

谢谢!

编辑 1:

包装/装饰 FileAppender 甚至 ConsoleAppender 的行为完全相同(在 log4net 官方配置示例中仍然有一个基本 BufferingForwardingAppender 包装/装饰 ConsoleAppender 的示例 .. 并且没有具体提到处理性能)。

经过一些调查/分析后，我可以看到大部分时间都在 BufferingForwardingAppender 内部被破坏，更具体地说是在调用 WindowsIdentity.GetCurrent() 时...每次我们调用 Log 时都会被调用.Debug() .. 在前面的示例中(在上面的示例源代码中有 100K 次)。

众所周知，调用此方法的成本非常高，应该避免或尽量减少，我真的不明白为什么每个日志事件都会调用它。 我真的完全错误地配置了某些东西/没有看到明显的东西，还是某处有某种错误，这就是我现在想弄清楚的......

部分调用栈是:

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get_UserName()

对 get_LocationInformation() 的调用也是在 FixVolatileData 中完成的，这也会导致高性能成本(每次都捕获堆栈跟踪)。

我现在试图理解为什么这个极其昂贵的 FixVolatileData 调用(至少对于所要求的修复)发生在这个上下文中的每个日志事件上，而直接通过包装的附加程序(直接通过 ConsoleAppender/FileAppender ..)不执行这种操作。

即将进行的更新，除非有人得到所有这些的答案；)

谢谢!

Answer 1

我发现了问题。

BufferingForwardingAppender继承自 BufferingAppenderSkeleton (与其他使用日志记录事件缓冲的附加程序一样，例如 AdoNetAppender、RemotingAppender、SmtpAppender ..)。

BufferingAppenderSkeleton一旦满足特定条件(例如缓冲区已满)，实际上是在将日志事件传递到目标附加程序之前缓冲日志事件。

根据 LoggingEvent 的文档类(代表一个日志记录事件，并包含事件的所有值(消息、threadid ...)):

Some logging events properties are considered "volatile", that is the values are correct at the time the event is delivered to appenders, but will not be consistent at any time afterwards. If an event is to be stored and the processed at a later time, these volatile values must be fixed by calling FixVolatileData. There is a performance penalty incurred by calling FixVolatileData but is is essential to maintain data consistency

这些“ volatile ”属性由 FixFlags 表示包含 Message、ThreadName、UserName、Identity 等标志的枚举......所有 volatile 属性。 它还包含标志“None”(不修复任何属性)、“All”(修复所有属性)和“Partial”(仅修复某个预定义的属性集)。

当 BufferingAppenderSkeleton被实例化时，默认情况下它将修复设置为“全部”，这意味着所有“ volatile ”属性都应该被修复。

在该上下文中，对于附加到 BufferingAppenderSkeleton 中的每个 LoggingEvent，所有“volatile”属性都将在事件插入缓冲区之前固定。这包括属性 Identity(用户名)和 LocationInformation(堆栈跟踪)，即使这些属性未包含在布局中(但我想如果稍后将布局更改为在缓冲区中包含这些属性，这会产生某种意义已经填充了 LoggingEvents)。

但是在我的情况下，这确实会损害性能。我没有在我的布局中包含 Identity 和 LocationInformation，也不打算这样做(主要是为了性能问题)

现在是解决方案......

BufferingAppenderSkeleton 中有两个属性可用于控制 FixFlags BufferingAppenderSkeleton 的标志值(默认情况下它再次设置为“ALL”，这不是很好!)。 这两个属性是Fix (FixFlags 类型)和 OnlyFixPartialEventData ( bool 类型)。

要微调标志值或禁用所有修复，Fix应该使用属性。

对于特定的部分预定义标志组合(不包括 Identity 或 LocationInfo)，OnlyFixPartialEventData可以通过将其设置为“true”来代替使用。

如果我重用上面的配置示例(在我的问题中)，为释放性能而对配置所做的唯一更改如下所示:

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
  <Fix value="0"/> <!-- Set Fix flag to NONE -->
</appender>

使用这个修改后的配置，我在上面的问题中提出的基准代码执行从大约 14000 毫秒下降到 230 毫秒(快 60 倍)! 如果我使用 <OnlyFixPartialEventData value="true"/>而不是禁用所有修复它需要大约 350 毫秒。

可悲的是，这个标志没有很好的记录(除了在 SDK 文档中，有一点)..所以我不得不深入挖掘 log4net 源来找到问题。

这尤其有问题，尤其是在“引用”配置示例中，此标志无处出现(http://logging.apache.org/log4net/release/config-examples.html)。 因此，为 BufferingForwardingAppender 和 AdoNetAppender(以及其他继承自 BufferingAppenderSkeleton 的附加程序)提供的样本会给用户带来糟糕的性能，即使他们使用的布局非常小。