BufferingForwardingAppender in log4net

https://blog.csdn.net/szx1999/article/details/50073857

7. 寫日誌會影響系統性能嗎？

寫日誌必然是會消耗必定資源的，而RollingFileAppender也不是線程安全的。爲了減少log4net影響系統性能的嫌疑，咱們加入lockingModel參數，使用FileAppender.MinimalLock來減小併發時發生死鎖的機率：

<param name="lockingModel" type="log4net.Appender.FileAppender+MinimalLock" />

儘管如此，文件的I/O始終是耗性能的，有沒有辦法緩存一批日誌，而後一次性寫入文件呢？BufferingForwardingAppender正是爲此而生，咱們下章再介紹如何使用它。

 

 

https://stackoverflow.com/questions/11319319/log4net-bufferingforwardingappender-performance-issue

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.

 

http://www.javashuo.com/article/p-zozpxpdv-r.html

 

http://www.nimaara.com/2016/01/01/high-performance-logging-log4net/

https://github.com/NimaAra/Easy.Logger

Problems with BufferingForwardingAppender

The BufferingForwardingAppender only flushes its events once the bufferSize is full unless you specify lossy to be true so this means if you have an application producing a single log event every 1 second you would have to wait 512 seconds for the batch to be flushed out. This may not be a problem for you and if it is not then I highly recommend using this forwarder as it has great GC and CPU performance but if you need real-time monitoring of every log entry and a higher throughput then continue reading.

Another point we should be aware of is that this forwarder is not asynchronous it merely batches the events so the application thread(s) producing the log events will be blocked while the buffer is being flushed out.

The solution

Having considered the points above, I thought I could do better so say hello to my little friend AsyncBufferingForwardingAppender.

This buffering forwarder uses a worker thread which batches up and flushes the log events in the background, it also detects if it has been idle meaning if there has not been enough log events to cause the buffer to be flushed it will invoke a manual flush which addresses the problem I mentioned above and since it is developed as a forwarder you can add additional appenders to it for example it can forward the log events to the Console, DB or any other appender that you might have all at the same time.