log4net的BufferingForwardingAppender性能问题(log4net Bu

2019-06-26 00:20发布

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

我在做的log4net的一些非常基本的基准测试,我试图装修RollingFileAppender进行了BufferingForwardingAppender。

我遇到可怕的性能通过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进行去输出为:

完成在511毫秒

而通过BufferingForwardingAppender装饰RollingFileAppender进行准备:

完成在14261毫秒

这是约30倍慢。

我以为我会通过缓冲一定量的日志将其写入到文件之前获得一些速度,但由于某种原因,把事情更糟。

在我看来,像配置是OK,所以这是非常奇怪的。

任何人都得到了线索?

谢谢!

编辑1:

该行为是严格包装/装饰FileAppender甚至是ConsoleAppender相同(还有提到与性能处理log4net的官方配置样品中基本BufferingForwardingAppender包装/装潢是ConsoleAppender ..并没有什么具体的例子)。

一些调查/分析后,我可以看到,大部分的时间是BufferingForwardingAppender内更具体宠坏的调用WindowsIdentity.GetCurrent()......被称为每次我们做一个呼叫Log.Debug() ..以前的样品(在上面的示例源100K次)英寸

此方法的调用被称为是非常昂贵的,应当避免或最小化,我真的不明白为什么它被调用为每个日志事件。 我真的完全错误配置的东西/没有看到什么明显的,或者是一个bug某处不知何故,这就是我想现在要弄清楚......

部分调用堆栈是:

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

要在通话get_LocationInformation()也在FixVolatileData完成后,引起了高PERF的成本以及(捕获堆栈每次跟踪)。

我现在想明白为什么这个极其昂贵FixVolatileData调用(至少在修复要求)会为每个日志事件在此背景下,而直接通过包裹附加器会(直接通过是ConsoleAppender / FileAppender ..)不执行这样的操作。

即将到来的更新跟随,除非有人得到了一个答案,这一切;)

谢谢!

Answer 1:

我发现了问题。

所述BufferingForwardingAppender从继承BufferingAppenderSkeleton (如同其他的appender利用记录事件缓冲如AdoNetAppenderRemotingAppenderSmtpAppender ..)。

BufferingAppenderSkeleton实际上是提供他们的appender一旦满足特定条件(缓冲区满为例)的目标其实之前缓冲记录事件。

根据的文件LoggingEvent类(表示记录事件,并包含该事件的所有值(消息,线程ID ...)):

一些记录事件的属性被认为是“挥发性”,即值是在事件被传递到附加目的地时是正确的,但不会是在任何时候保持一致之后。 如果事件是要被存储并在稍后的时间处理后,这些挥发性值必须被固定bycalling FixVolatileData。 有通过调用FixVolatileData招致的性能损失,但重要的是要保持数据的一致性

这些“挥发性”属性由表示FixFlags含有标志如消息,ThreadName,用户名,标识...所以所有挥发性属性枚举。 它还包含标志“无”(无固定属性),“全部”(修复所有属性)和“部分”(仅固定属性的某些预定义DSET)。

Whem的BufferingAppenderSkeleton被实例化,默认情况下它设置为“所有”,这意味着所有的“挥发性”性质应该是固定的固定。

在这种情况下,对于附加到每个BufferingAppenderSkeleton LoggingEvent所,ALL“挥发性”属性将被插入在缓冲器中的事件之前固定。 这包括性能标识(用户名)和LocationInformation(堆栈跟踪),即使这些属性不包含在布局(但我想这是某种有道理的,如果布局发生变化的同时缓冲以后,包括这些属性已经已经充满LoggingEvents)。

然而,在我的情况下,这真的很痛性能。 我不包括在我的布局的身份和LocationInformation和不打算(主要针对性能问题)

现在的解决方案...

有两种性质BufferingAppenderSkeleton可以用来控制FixFlags中的标志值BufferingAppenderSkeleton (默认情况下再次将其设置为“ALL”,这是不是很漂亮!)。 这两种性质是Fix (FixFlags型)和OnlyFixPartialEventData (布尔型)。

对于标志值或禁用所有修复微调,将Fix应采用性能。 对于标志(不包括身份或LocationInfo)的特定部分的预定义组合中, OnlyFixPartialEventData可以代替通过设置为“真”使用。

如果我再利用上面配置方案(在我的问题),对配置的发动性能而做出的唯一改变是如下所示:

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

使用这种修改过的配置,基准代码执行上面我的问题提出,是从下降约14000ms到230ms(60X快)! 和,如果我使用<OnlyFixPartialEventData value="true"/>而不是禁用所有修复它是约350毫秒取。

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

这是特别有问题的,特别是“参考”配置样品中时,该标志出现无处(http://logging.apache.org/log4net/release/config-examples.html)。 因此,提供BufferingForwardingAppender和AdoNetAppender(和其他的appender从BufferingAppenderSkeleton继承)样品将开放给用户TERRIBLE性能,即使他们使用的布局相当小。



Answer 2:

难道那是因为你没有指定在布局模式BufferingForwardingAppender但你是在RollingLogFileAppender因此BufferingForwardingAppender是包括一切都在它是包括用户名(%用户名)输出

以下是一个在模式布局选项列表中的一个有趣的博客文章,它看起来像他有几个人被标记为慢。

http://www.beefycode.com/post/Log4Net-Tutorial-pt-4-Layouts-and-Patterns.aspx



文章来源: log4net BufferingForwardingAppender performance issue