log4net的BufferingForwardingAppender性能问题 [英] log4net BufferingForwardingAppender performance issue

问题描述

编辑2：我已经解决了这个问题（见下文接听）请注意，这个问题可能会影响到饰BufferingForwardingAppender以及所有附加目的地从BufferingAppenderSkeleton继承所有附加目的地（分别为：AdoNetAppender，RemotingAppender，SmtpAppender和SmtpPickupDirAppender） *

我在做的log4net的一些非常基本的基准测试，我试图装饰用BufferingForwardingAppender一个RollingFileAppender进行。

我遇到可怕的性能通过BufferingForwardingAppender去，而不是直接通过RollingFileAppender进行，我真的不明白的原因

下面是我的配置：

<预类=郎咸平的XML prettyprint-覆盖> <追加程序名称=RollingLogFileAppenderTYPE =log4net.Appender.RollingFileAppender>
<文件值=C：\/>
< appendToFile值=FALSE/>
< rollingStyle值=复合/>
< datePattern值='。'MMDD-HH'.log'/>
< maxSizeRollBackups值=168/>
< staticLogFileName值=FALSE/>
<布局类型=log4net.Layout.PatternLayout>
< conversionPattern值=％DATE [％线程]％-5level％记录仪 - 消息％换行符％/>
< /布局>
< /附加器>

<追加程序名称=BufferingForwardingAppenderTYPE =log4net.Appender.BufferingForwardingAppender>
< BUFFERSIZE值=512/>
<附加目的地-REF REF =RollingLogFileAppender/>
< /附加器>

<根和GT;
<电平值=DEBUG/>
<附加目的地-REF REF =BufferingForwardingAppender/>
< /根>


这是基准（非常简单的代码）：

  VAR秒表=新的秒表（）; 
 stopWatch.Start（）; 
的for（int i = 0; I< 100000;我++）
 {
 Log.Debug（你好）; 
} 
 stopWatch.Stop（）; 
 Console.WriteLine（完成于{0}毫秒，stopWatch.ElapsedMilliseconds）; 
  

直接通过RollingFileAppender进行展望的输出是：

< BLOCKQUOTE>

在511毫秒完成

而经历的BufferingForwardingAppender装饰RollingFileAppender进行：

完成在14261毫秒

这是约30倍慢。

我想我会通过缓冲一定量的日志将其写入文件之前获得一些速度，但由于某种原因把事情更糟。

在我看来，像配置是OK，所以这是非常奇怪的。

任何人都得到了线索？

谢谢！

修改1：

该行为是严格按照包装/装饰FileAppender甚至是ConsoleAppender（同样还有基本的例子log4net的官方配置样本中BufferingForwardingAppender包装/装潢是ConsoleAppender ..并没有具体提到与性能处理）。

一番调查/分析后，我可以看到，大部分的时间是BufferingForwardingAppender内更具体到WindowsIdentity.GetCurrent（）的调用宠坏了......被称为每次我们作出来 Log.Debug（） ..通话以前的样本（在上面的示例源10万次）。

调用此方法被称为是非常昂贵的，应当避免或最小化，我真的不明白为什么它被调用为每个日志事件。
我真能完全地错误的东西/没有看到明显的东西，或者是一个bug某处不知何故，这就是我想现在要搞清楚...

局部调用堆栈是：

• AppenderSkeleton.DoAppend


• BufferingAppenderSkeleton.Append


• LoggingEvent.FixVolatileData
  
• LoggingEvent.get_UserName（）

到 A调用get_LocationInformation（）也在FixVolatileData完成，招致了高PERF的成本以及（捕获堆栈跟踪每个时间）。

我现在正试图（通过直接是ConsoleAppender / FileAppender ..）理解为什么这种极其昂贵的FixVolatileData调用（至少在修复要求）会为每个日志事件在这方面，而直接通过包裹附加目的地去。不执行这样的操作

即将更新跟进，除非有人得到了一个答案，这一切;）

谢谢！

解决方案

我发现了问题。

在 BufferingForwardingAppender 是 BufferingAppenderSkeleton （因为是其他的appender利用记录事件的缓冲，如 AdoNetAppender ， RemotingAppender ， SmtpAppender ..）。

实际上他们提供给目标附加器一旦条件满足之前， BufferingAppenderSkeleton 实际上是缓冲记录事件（缓冲区满为例）

（代表日志事件，并包含所有值（消息，主题ID按照 LoggingEvent所类的文档...）活动的）：

属性被认为是易失性一些记录事件，即$ b $的b值是正确的时间的事件被传递到附加目的地，
，但不会在任何时间一致之后。如果事件是要
被存储并在稍后的时间的处理，这些挥发性值
必须固定bycalling FixVolatileData。有通过调用FixVolatileData招致性能
点球，但就是
必不可少的保持数据的一致性。

这些易变属性由 FixFlags代表含标志，如消息，ThreadName，用户名，身份......因此，所有挥发性的属性枚举。
它还包含标志无（修复无属性），全部（修复所有属性）和部分（仅修复性能有一定的预定义DSET）。

Whem的 BufferingAppenderSkeleton 被实例化，默认情况下它设置固定为所有，这意味着所有的动荡的属性应该是固定的。

在这种情况下，对于附加到BufferingAppenderSkeleton每个LoggingEvent所，ALL挥发性属性将被插入在缓冲器中的事件之前固定。这包括性能标识（用户名）和LocationInformation（堆栈跟踪），即使这些属性不包括在布局（但我想这是某种有道理的，如果布局发生变化的同时，缓冲以后，包括这些属性已经已经充满LoggingEvents）。

然而，在我的情况下，这个好痛性能。我不包括在我的布局的身份和LocationInformation和不打算（主要针对性能问题）

现在的解决方案...

有在 BufferingAppenderSkeleton 两个属性可以用来控制 FixFlags 的 BufferingAppenderSkeleton 的标志值（再次默认情况下它被设置为所有，这是不是很漂亮！）。
这两个属性是修复（FixFlags型）和 OnlyFixPartialEventData （布尔型）。

有关的标志值的微调或禁用所有修复，在修复属性应该被使用。
。对于标志（不包括身份或LocationInfo）的特定部分预定义的结合， OnlyFixPartialEventData 可以用来代替通过将其设置为真。

如果我重新使用上述配置示例（在我的问题），到配置，释放性能而做出的唯一的变化是指示如下：

 <追加程序名称=BufferingForwardingAppenderTYPE =log4net.Appender.BufferingForwardingAppender> 
< BUFFERSIZE值=512/> 
<附加目的地-REF REF =RollingLogFileAppender/> 
<修正值=0/> <！ - 集修复标志为NONE  - > 
< /附加器> 
  

使用这个修改后的配置，基准代码执行上面我的问题提出，是从约 14000ms为230ms（60X更快）
如果我用< OnlyFixPartialEventData值=真/>将，而不是禁用所有修复它是大约350毫秒服用。

不幸的是，这个标志是不是非常有据可查（除了SDK文档，一点点）..所以我不得不深入挖掘log4net的来源，以找到该问题。

这是特别有问题，特别是参考配置样本中，该标志将出现无处（http://logging.apache.org/log4net/release/config-examples的.html）。
以便提供用于BufferingForwardingAppender的样品中，和AdoNetAppender（和其他追加程序从BufferingAppenderSkeleton继承）会给TERRIBLE表现给用户，即使他们正在使用的布局是相当小

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!

解决方案

I found out the issue.

The BufferingForwardingAppender is inheriting from BufferingAppenderSkeleton (as are other appenders making use of logging events buffering such as AdoNetAppender, RemotingAppender, SmtpAppender ..).

The BufferingAppenderSkeleton is actually buffering logging events before actually delivering them to the target appender once a certain condition is met (buffer full for example).

According to documentation of the LoggingEvent class (representing a logging event, and containing all values (message, threadid ...) of the event) :

Some logging events properties are considered "volatile", that is the values are correct at the time the event is delivered to appenders, but will not be consistent at any time afterwards. If an event is to be stored and the processed at a later time, these volatile values must be fixed bycalling FixVolatileData. There is a performance penalty incurred by calling FixVolatileData but is is essential to maintain data consistency

These "volatile" properties are represented by the FixFlags enumeration containing flags such as Message, ThreadName, UserName, Identity ... so all volatile properties. It also contains the flag "None" (fix no properties), "All" (fix all properties) and "Partial" (fix only a certain predefine dset of properties).

Whem the BufferingAppenderSkeleton is instanciated, by DEFAULT it sets the fixing to "All" meaning that all "volatile" properties should be fixed.

In that context, for each LoggingEvent appended into the BufferingAppenderSkeleton, ALL "volatile" properties will be fixed before the event is inserted in the buffer. This includes the properties Identity (username) and LocationInformation (stack trace) even if these properties are not included in the layout (but I guess it makes some kind of sense if the layout is changed to include these properties at a later time while a buffer has been already been filled with LoggingEvents).

However in my case this really HURTS performance. I am not including the Identity and LocationInformation in my layout and don't plan to (mainly for performance issues)

Now for the solution ...

There are two properties in BufferingAppenderSkeleton which can be used to control the FixFlags flag value of the BufferingAppenderSkeleton (once again by default it is set to "ALL" which is not very nice !). These two properties are Fix (FixFlags type) and OnlyFixPartialEventData (bool type).

For a fine tune of the flag value or to disable all fix, the Fix property should be used. For a specific partial predefined combination of flags (not including Identity or LocationInfo), the OnlyFixPartialEventData can be used instead by setting it to "true".

If I reuse the configuration sample above (in my question), the only change made to the configuration to unleash performance is indicated below:

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
  <Fix value="0"/> <!-- Set Fix flag to NONE -->
</appender>

Using this modified configuration, the benchmark code execution presented in my question above, is dropping from approx 14000ms to 230ms (60X faster) ! And if I use <OnlyFixPartialEventData value="true"/> instead of disabling all fix it is taking approx 350ms.

Sadly, this flag is not very well documented (except in the SDK documentation, a little bit) .. so I had to dig deep into log4net sources to find the issue.

This is particularly problematic especially in the "reference" configuration samples, this flag appears nowhere (http://logging.apache.org/log4net/release/config-examples.html). So the samples provided for BufferingForwardingAppender, and AdoNetAppender (and other appenders inheriting from BufferingAppenderSkeleton) will give TERRIBLE performance to users, even if the layout they are using is pretty minimal.

这篇关于log4net的BufferingForwardingAppender性能问题的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！