log4net BufferingForwardingAppender性能问题
编辑2:我已经解决了问题(请参阅下面的答案)请注意,该问题可能会影响所有使用BufferingForwardingAppender修饰的appender以及从BufferingAppenderSkeletoninheritance的所有appender(分别为:AdoNetAppender,RemotingAppender,SmtpAppender和SmtpPickupDirAppender)*
我正在做一些非常基本的log4net工作台,我试图用BufferingForwardingAppender修饰RollingFileAppender。
我通过BufferingForwardingAppender而不是直接通过RollingFileAppender遇到了糟糕的性能,我真的没有理由。
这是我的配置:
这是基准(非常简单的代码):
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倍。
我认为通过在将它们写入文件之前缓冲一定量的日志来获得一些速度,但是由于某种原因它会使事情变得更糟。
在我看来配置是好的,所以这真的很奇怪。
有人知道吗?
谢谢!
编辑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调用(至少对于修复问题)在这个上下文中发生的每个日志事件,而直接通过包装的appender(直接通过ConsoleAppender / FileAppender ..)不会执行这种操作。
即将到来的更新,除非有人得到了所有这些的答案;)
谢谢!
我发现了这个问题。
BufferingForwardingAppender
inheritance自BufferingAppenderSkeleton
(与使用记录事件缓冲的其他appender一样,如AdoNetAppender
, RemotingAppender
, SmtpAppender
……)。
BufferingAppenderSkeleton
实际上是在满足特定条件(例如缓冲区已满)之前将日志事件实际传送到目标appender之前缓冲日志事件。
根据LoggingEvent
类的文档(表示日志记录事件,并包含事件的所有值(message,threadid …)):
某些日志记录事件属性被视为“易失性”,即在事件传递给追加者时值是正确的,但之后的任何时间都不一致。 如果要存储事件并在以后处理,则必须通过调用FixVolatileData来修复这些易失性值。 调用FixVolatileData会导致性能下降,但这对于维护数据一致性至关重要
这些“volatile”属性由包含Message,ThreadName,UserName,Identity等标志的FixFlags
枚举表示,因此所有volatile属性。 它还包含标志“None”(不修复任何属性),“All”(修复所有属性)和“Partial”(仅修复某个预定义的dset属性)。
通过DEFAULT将BufferingAppenderSkeleton
为实例,它将修复设置为“All”,这意味着应该修复所有“volatile”属性。
在该上下文中,对于附加到BufferingAppenderSkeleton中的每个LoggingEvent,在将事件插入缓冲区之前,将修复所有“volatile”属性。 这包括属性Identity(用户名)和LocationInformation(堆栈跟踪),即使这些属性未包含在布局中(但我想如果布局被更改为稍后在缓冲区中包含这些属性时会有某种意义已经填充了LoggingEvents)。
但在我的情况下,这真的是HURTS的表现。 我没有在我的布局中包含Identity和LocationInformation并且不打算(主要是针对性能问题)
现在为解决方案……
BufferingAppenderSkeleton
有两个属性可用于控制BufferingAppenderSkeleton
的FixFlags
标志值(默认情况下,它再次设置为“ALL”,这不是很好!)。 这两个属性是Fix
(FixFlags类型)和OnlyFixPartialEventData
(bool类型)。
要对标志值进行微调或禁用所有修复,应使用Fix
属性。 对于特定的部分预定义标志组合(不包括Identity或LocationInfo),可以通过将其设置为“true”来使用OnlyFixPartialEventData
。
如果我重用上面的配置示例(在我的问题中),则对配置进行的唯一更改以释放性能如下所示:
使用这个修改过的配置,我在上面的问题中提出的基准代码执行从大约14000ms下降到230ms(快60倍)! 如果我使用
而不是禁用所有修复它需要大约
。
遗憾的是,这个标志没有很好的记录(除了在SDK文档中,一点点)..所以我不得不深入挖掘log4net来源以找到问题。
这特别成问题,尤其是在“参考”配置示例中,此标志无处可见(http://logging.apache.org/log4net/release/config-examples.html)。 因此,为BufferingForwardingAppender提供的示例和AdoNetAppender(以及inheritance自BufferingAppenderSkeleton的其他appender)将为用户提供可怕的性能,即使他们使用的布局非常小。
是否有可能是因为你没有在BufferingForwardingAppender
指定布局模式但是你在RollingLogFileAppender
因此BufferingForwardingAppender
包含其输出中的所有内容,包括用户名(%username)
下面是一篇有趣的博客文章,其中列出了模式布局中的选项,看起来他有几个标记为慢速。
http://www.beefycode.com/post/Log4Net-Tutorial-pt-4-Layouts-and-Patterns.aspx