dar*_*key 22 c# performance log4net appender
编辑2:我已经解决了问题(请参阅下面的答案)请注意,该问题可能会影响所有使用BufferingForwardingAppender修饰的appender以及从BufferingAppenderSkeleton继承的所有appender(分别为: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毫秒
而通过BufferingForwardingAppender装饰RollingFileAppender:
订单日期为14261毫秒
这大约慢了30倍.
我认为通过在将它们写入文件之前缓冲一定量的日志来获得一些速度,但是由于某种原因它会使事情变得更糟.
在我看来配置是好的,所以这真的很奇怪.
有人知道吗？
谢谢!
编辑1:
通过包装/装饰FileAppender甚至是ConsoleAppender,行为完全相同(在log4net官方配置示例中仍然有一个基本的BufferingForwardingAppender包装/装饰ConsoleAppender的例子......并且没有具体提到处理性能).
经过一些调查/分析后,我可以看到大部分时间都在BufferingForwardingAppender中被破坏,更具体地说是在调用WindowsIdentity.GetCurrent()...被调用的时候我们Log.Debug()在前一个样本中调用..在上面的样本源中100K次).
已知对此方法的调用非常昂贵,应该避免或最小化,我真的不明白为什么它会被调用每个日志事件.我真的完全错误地配置了某些东西/没有看到明显的东西,或者某种错误是某种错误,这就是我现在想要解决的问题......
部分调用堆栈是:
调用get_LocationInformation()也在FixVolatileData中完成,也会导致高性能(每次捕获堆栈跟踪).
我现在试图理解为什么这个极其昂贵的FixVolatileData调用(至少对于修复问题)在这个上下文中发生的每个日志事件,而直接通过包装的appender(直接通过ConsoleAppender/FileAppender ..)不执行这种操作.
即将到来的更新,除非有人得到了所有这些的答案;)
谢谢!
dar*_*key 39
我发现了这个问题.
的BufferingForwardingAppender是从继承BufferingAppenderSkeleton(如同其他的appender利用记录事件的缓冲如AdoNetAppender,RemotingAppender,SmtpAppender..).
在BufferingAppenderSkeleton实际提供他们的appender一旦满足特定条件(缓冲区满为例)的目标之前实际上是缓冲记录事件.
根据LoggingEvent类的文档(表示日志记录事件,并包含事件的所有值(message,threadid ...)):
某些日志记录事件属性被视为"易失性",即在事件传递给追加者时值是正确的,但之后的任何时间都不一致.如果要存储事件并在以后处理,则必须通过调用FixVolatileData来修复这些易失性值.调用FixVolatileData会导致性能下降,但这对于维护数据一致性至关重要
这些"volatile"属性由FixFlags包含标志的枚举表示,例如Message,ThreadName,UserName,Identity ...所以所有volatile属性.它还包含标志"None"(不修复属性),"All"(修复所有属性)和"Partial"(仅修复某个预定义的dset属性).
Whem将BufferingAppenderSkeleton被实例化,默认情况下它设置为"所有",这意味着所有的"挥发性"性质应该是固定的固定.
在该上下文中,对于附加到BufferingAppenderSkeleton中的每个LoggingEvent,在将事件插入缓冲区之前,将修复所有"volatile"属性.这包括属性Identity(用户名)和LocationInformation(堆栈跟踪),即使这些属性不包含在布局中(但我想如果布局被更改为稍后在缓冲区中包含这些属性时会有某种意义已经填充了LoggingEvents).
但在我的情况下,这真的是HURTS表现.我没有在我的布局中包含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>
使用这个修改过的配置,我在上面的问题中提出的基准代码执行从大约14000ms下降到230ms(快60倍)!
如果我使用<OnlyFixPartialEventData value="true"/>而不是禁用所有修复它需要大约350毫秒.
遗憾的是,这个标志没有很好的记录(除了在SDK文档中,一点点)..所以我不得不深入研究log4net来源以找到问题.
这特别成问题,特别是在"参考"配置示例中,此标志无处可见(http://logging.apache.org/log4net/release/config-examples.html).因此,为BufferingForwardingAppender和AdoNetAppender(以及继承自BufferingAppenderSkeleton的其他appender)提供的示例将为用户提供可怕的性能,即使他们使用的布局非常小.