编辑 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 ..)不执行此类操作。
即将更新,除非有人已经回答了所有这些问题;)
谢谢!