编辑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 ..)不执行这样的操作。
即将到来的更新跟随,除非有人得到了一个答案,这一切;)
谢谢!