log4net缓冲转发附加器性能问题

29

编辑 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 的输出为:

用时 511 毫秒

然而,使用装饰了RollingFileAppender的 BufferingForwardingAppender 输出结果为:

用时 14261 毫秒

这大约是慢了30倍。

我原本认为在写入日志文件之前缓冲一定数量的日志会提高速度,但由于某种原因情况变得更糟了。

似乎配置没有问题,所以这真的很奇怪。

有人知道是什么原因吗?

谢谢!

编辑1:

无论是包装/装饰一个 FileAppender 还是 ConsoleAppender(log4net 官方配置示例中仍有基本 BufferingForwardingAppender 包装/装饰 ConsoleAppender 的示例.. 但没有特别提到处理性能的内容)行为都是完全相同的。

经过一些调查/分析,我可以看到大部分时间都花费在 BufferingForwardingAppender 内部,具体来说是在每次调用Log.Debug()时调用 WindowsIdentity.GetCurrent()… 在上面的样本源代码中调用了 10 万次。

已知调用此方法的成本很高,应该避免或最小化,我真的不明白为什么每个日志事件都要调用它。

我是否真的完全配置错误/没有看到一些显而易见的东西,或者这是某种 bug,在某处出现,这就是我现在试图弄清楚的事情...

部分调用栈如下:

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

调用get_LocationInformation()也在 FixVolatileData 中完成,产生了很高的性能成本(每次捕获堆栈跟踪)。

我现在正在尝试理解为什么在这种情况下会为每个日志事件发生此极其昂贵的 FixVolatileData 调用(至少对于所要求的修复),而直接通过包装的 appender(直接通过 ConsoleAppender/FileAppender ..)不执行此类操作。

即将更新,除非有人已经回答了所有这些问题;)

谢谢!

2个回答

49
我找到了问题所在。
`BufferingForwardingAppender` 继承自 `BufferingAppenderSkeleton`(其他使用日志事件缓冲的 appender 也是如此,例如 `AdoNetAppender`、`RemotingAppender`、`SmtpAppender` 等)。
实际上,在将 logging 事件传递到目标 appender 之前,`BufferingAppenderSkeleton` 会缓冲这些事件,直到满足某个条件(比如 buffer 已满)。
根据 `LoggingEvent` 类的文档(表示一个 logging 事件,并包含事件的所有值(消息、线程 ID 等)):
"某些 logging 事件属性被视为“volatile”,即值在事件传递到 appenders 时是正确的,但在此之后任何时间都不一致。如果要存储事件并在以后处理它们,则必须通过调用 `FixVolatileData` 来修复这些 volatile 值。虽然调用 `FixVolatileData` 会产生性能损失,但它是保持数据一致性的必要操作。”
这些“volatile”属性由 `FixFlags` 枚举表示,其中包含诸如 Message、ThreadName、UserName、Identity 等所有 volatile 属性的标志。它还包括 None(不修复任何属性)、All(修复所有属性)和Partial(仅修复一组预定义属性)标志。
当 `BufferingAppenderSkeleton` 被实例化时,默认情况下它将 fixing 设置为“ALL”,这意味着所有“volatile”属性都应该被修复。
在此情况下,对于附加到 `BufferingAppenderSkeleton` 中的每个 LoggingEvent,在事件插入缓冲区之前,所有“volatile”属性都将被修复。这包括 Identity(用户名)和 LocationInformation(堆栈跟踪)属性,即使这些属性未包含在布局中(但我猜如果在填充 LoggingEvents 缓冲区时稍后更改布局以包含这些属性,则会有一定意义)。
然而,在我的情况下,这真的会损害性能。我没有在布局中包含 Identity 和 LocationInformation,并且不打算这样做(主要是出于性能问题)。
现在来看解决方案…
`BufferingAppenderSkeleton` 中有两个属性可用于控制 `BufferingAppenderSkeleton` 的 `FixFlags` 标志值(再次,默认设置为“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>

使用这个修改后的配置,我在问题中提出的基准代码执行时间从约14000ms降至230ms(快了60倍)! 如果我使用<OnlyFixPartialEventData value="true"/>代替禁用全部修复,则需要大约350ms。

可悲的是,这个标志没有很好的文档记录(除了SDK文档有一点点),所以我不得不深入研究log4net源代码才能找到问题。

这在“参考”配置示例中特别有问题,因为这个标志根本没有出现(http://logging.apache.org/log4net/release/config-examples.html)。 因此,对于使用BufferingForwardingAppender和AdoNetAppender(以及其他从BufferingAppenderSkeleton继承的追加器)的用户而言,即使他们使用的布局非常简单,性能也会非常糟糕。


3
你好,我们正在记录线程、异常和自定义字段ID。我们使用的是log4net.Appender.AdoNetAppender。我们尝试指定<Fix="0"/>,结果停止记录线程和异常的值。此外,自定义id字段开始出现记录错误。虽然性能提高了近10倍。你能给出任何线索吗? - Milind Thakkar
对于 AdoNetAppender,您需要确保这些问题得到解决。请在此参考文档中累加需要修复的内容值:http://logging.apache.org/log4net/release/sdk/log4net.Core.FixFlags.html - Berin Loritsch
感谢您提供的解决方案!所以“RollingFileAppender”的最终数字是511毫秒,而“BufferingForwardingAppender”则为230毫秒或350毫秒(取决于配置)?这确实是一个改进,但并不像我想象的那么令人印象深刻... - Josep
你可以不采用激进的优化方式进行“修复”(fixing)none,仍然能够获得线程ID、修复异常,参考这篇文章 -- https://logging.apache.org/log4net/log4net-1.2.13/release/sdk/log4net.Core.FixFlags.html - Eugene D. Gubenkov

1

可能是因为您在BufferingForwardingAppender中没有指定布局模式,但在RollingLogFileAppender中却有,因此BufferingForwardingAppender将所有内容都包含在其输出中,包括用户名(%username)。

以下是一篇有趣的博客文章,列出了模式布局中的选项列表,看起来他将其中几个标记为缓慢。

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


你好,谢谢你的回答! 我之前已经考虑过并尝试了在BufferingForwardingAppender里指定与RollingFileAppender相同的布局模式,但不幸的是这并没有解决问题。 最终,我找到了修复方法,需要仔细研究log4net源代码。实际上,BufferingForwardingAppender(或BufferingAppenderSkeleton)有一个属性应该设置为特定值。然而,这个属性完全没有被记录在文档中(除了SDK文档,但也不够清晰)。我很快会回答我的问题,并提供所有细节。 - darkey
很奇怪,即使是最新的log4net源代码,这个问题仍然存在。如果我弄清楚了,我会添加我的发现。 - justdan23
好的,所以在Log4Net的LoggingEvent类中,有一个名为FixFlags的枚举。该枚举包含了所有“修复”选项的可能值。注释还指出了哪些选项会显著影响性能。 - justdan23

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接