26

EDIT 2 : I have solved the problem (see answer below) Please note that the problem potentially affects all appenders decorated with BufferingForwardingAppender as well as all appenders inheriting from BufferingAppenderSkeleton (respectively : AdoNetAppender, RemotingAppender, SmtpAppender and SmtpPickupDirAppender) *

I was doing some very basic benchs of log4net and I tried to decorate a RollingFileAppender with a BufferingForwardingAppender.

I experience terrible performance going through the BufferingForwardingAppender instead of directly through the RollingFileAppender and I really don't get the reason.

Here is my configuration:

<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>

And here is the benchmark (very simple code):

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);

Going directly through RollingFileAppender the output is:

Done in 511 ms

Whereas going through the BufferingForwardingAppender decorating the RollingFileAppender :

Done in 14261 ms

That's approx 30 times slower.

I thought I would gain some speed by buffering a certain amount of log before writing them to the file, however for some reason it gets things much worse.

Seems to me like the configuration is OK, so this is really weird.

Anyone got a clue?

Thanks!

EDIT 1 :

The behavior is strictly the same by wrapping/decorating a FileAppender or even ConsoleAppender (still there is an example of basic BufferingForwardingAppender wrapping/decorating ConsoleAppender in log4net official config samples .. and nothing specific mentioned dealing with performance).

After some investigation/profiling, I can see that the majority of the time is spoiled inside the BufferingForwardingAppender more specifically in a call to WindowsIdentity.GetCurrent() ... being called EACH time we make a call to Log.Debug() .. in the previous sample (100K times in the sample source above).

Calls to this method are known to be very costly and should be avoided or minimized, I really don't get why it gets called for each log event. Am I really completely misconfiguring something / not seeing something evident, or is that a bug somehow somewhere, this is what I am trying to figure out now...

The partial call stack is :

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

A call to get_LocationInformation() is also done in FixVolatileData, incurring an high perf cost as well (capture the stack trace each time).

I am now trying to understand why this extremely costly FixVolatileData call (at least for the fix asked) happens for each log event in this context whereas going directly through the wrapped appender (directly through ConsoleAppender/FileAppender ..) does not perform this kind of operation.

Upcoming update to follow, unless someone got an answer to all of this ;)

Thanks!

4

2 回答 2

45

我发现了这个问题。

BufferingForwardingAppender继承自（与其他使用日志事件缓冲的附加程序一样，BufferingAppenderSkeleton例如AdoNetAppender, RemotingAppender, SmtpAppender..）。

BufferingAppenderSkeleton一旦满足特定条件（例如缓冲区已满），实际上是在将日志事件实际交付给目标附加程序之前缓冲日志记录事件。

根据LoggingEvent该类的文档（代表一个日志事件，并包含事件的所有值（消息、threadid ...））：

一些日志记录事件属性被认为是“易失的”，即在事件传递给附加程序时值是正确的，但在之后的任何时候都不会保持一致。如果要存储事件并在以后处理，则必须通过调用 FixVolatileData 来修复这些易失性值。调用 FixVolatileData 会导致性能损失，但对于保持数据一致性至关重要

这些“易失性”属性由FixFlags包含诸如 Message、ThreadName、UserName、Identity 等标志的枚举表示，因此所有易失性属性。它还包含标志“None”（不修复任何属性）、“All”（修复所有属性）和“Partial”（仅修复某个预定义的属性集）。

在BufferingAppenderSkeleton实例化的情况下，默认情况下它将修复设置为“全部”，这意味着所有“易失性”属性都应该被修复。

在这种情况下，对于附加到 BufferingAppenderSkeleton 的每个 LoggingEvent，所有“易失性”属性都将在事件插入缓冲区之前修复。这包括属性 Identity （用户名）和 LocationInformation （堆栈跟踪），即使这些属性未包含在布局中（但我想如果稍后将布局更改为包含这些属性，而缓冲区已被 LoggingEvents 填充）。

然而，在我的情况下，这真的很伤人的表现。我没有在我的布局中包含 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>

使用此修改后的配置，我在上面的问题中提出的基准代码执行从大约14000 毫秒下降到 230 毫秒（快 60 倍）！ 如果我使用<OnlyFixPartialEventData value="true"/>而不是禁用所有修复，则大约需要 350 毫秒。

可悲的是，这个标志没有很好的记录（除了在 SDK 文档中，一点点）.. 所以我不得不深入挖掘 log4net 源来找到问题。

这尤其是在“参考”配置示例中特别成问题，该标志无处出现（http://logging.apache.org/log4net/release/config-examples.html）。因此，为 BufferingForwardingAppender 和 AdoNetAppender（以及从 BufferingAppenderSkeleton 继承的其他附加程序）提供的示例将为用户提供可怕的性能，即使他们使用的布局非常小。

于 2012-07-05T19:40:00.080 回答
1

是否有可能是因为您没有在其中指定布局模式，BufferingForwardingAppender但您在其中，RollingLogFileAppender因此BufferingForwardingAppender包括其输出中的所有内容，包括用户名 (%username)

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

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

于 2012-07-05T15:02:45.070 回答