Thursday, February 13, 2014

.NET low latency logging. Part 7 - Improving performnace of asynchronous log4net solutions

Investigation of log4net performance issues

Since my previous post I made some experiments to improve the log4j2 performance in case of fast asynchronous appenders.

1) First of all I must say that using ForwardingAppender and its base class AppenderSkeleton for async forwarding appenders is a bad idea. I made some profiling investigations nad found that the following code fragment in AppenderSkeleton works too slow under a heavy load because of 'lock(this)' statement:

2) My second small improvement is to get rid of FixFlags.Message from FixFlags. In this case logging messages stay unchanged in log files, but performance will be improved cause of removing unnecessary string format during fixing the LoggingEvent. My current optimized fix flags configuration for all async appenders - FixFlags.ThreadName | FixFlags.Exception

3) Also I found that FileAppender and RollingFileAppender have an option ImmediateFlush which is enabled by default. It means that every logging event append operation into this appenders will be followed by slow Flush() call. Therefore I turned off this option in my FileAppender & RollingFileAppender configuration - <immediateFlush value="false" />

4) I must say that after all my optimizations BlockingCollection showed dramatically bad performance for the big count of producing threads (in my case > 16) and only one consuming thread. Profiler showed that problem in the BlockingCollection.Add() method.

NullAppenderEx

There is an improved version of NullAppender:

Performance of the NullAppenderEx

Let's compare its performance to the previous version:

AsyncForwardingAppenderBlockingEx, AsyncForwardingAppenderHotSwapEx, AsyncForwardingAppenderDisruptorEx

There are improved version of all my async log4net solutions:
The current configuration file is the following:

Performance of the AsyncForwardingAppenderHotSwapEx, AsyncForwardingAppenderDisruptorEx with the NullAppenderEx

Let's compare performance of the AsyncForwardingAppenderHotSwapEx, AsyncForwardingAppenderDisruptorEx with the NullAppenderEx to the previous version. Note that I completely removed AsyncForwardingAppenderBlockingEx from the result because is performs bad and extremely bad for many producing threads!

Performance of the AsyncForwardingAppenderHotSwapEx, AsyncForwardingAppenderDisruptorEx with the RollingFileAppender

Let's compare performance of the AsyncForwardingAppenderHotSwapEx, AsyncForwardingAppenderDisruptorEx with the RollingFileAppender to the previous version. Note that I completely removed AsyncForwardingAppenderBlockingEx from the result because is performs bad and extremely bad for many producing threads!

Conclusions

  • ForwardingAppender and its base class AppenderSkeleton are not fast enough to be used in low latency logging. I removed them from all my async appenders by explicit inheriting from core log4net interfaces - IAppender, IBulkAppender, IOptionHandler
  • I removed FixFlags.Message fix flag (see FixFlags) from my async logging configuration as it is not necessary for logging message representation, but wastes extra time on string format. My current optimized fix flags configuration for all async appenders - FixFlags.ThreadName | FixFlags.Exception
  • Performance of the log4net file appenders (FileAppender and RollingFileAppender) depends on ImmediateFlush option, which is turned on by default. Therefore I turned off this option in my FileAppender & RollingFileAppender configuration - <immediateFlush value="false" />
  • AsyncForwardingAppenderBlockingEx lost in the competition because of very bad performance of the BlockingCollection in case of many producing threads (in my case > 16)
  • I managed to get very good performance of optimized AsyncForwardingAppenderHotSwapEx and AsyncForwardingAppenderDisruptorEx appenders with fast NullAppenderEx
  • I still believe there is a good point to optimize the very slow FileAppender and RollingFileAppender in a way of using fast files to get similar performance as RandomAccessFileAppender shows in log4j2

3 comments:

  1. Note: Title : "performnace" => "performance"
    :-)

    ReplyDelete
  2. Great work btw. Very nicely and concisely presented too.

    ReplyDelete
  3. Great work.

    Do you thing that it is possible to show ASP.NET session identifier in log entries when using AsyncForwardingAppenderHotSwapEx / AsyncForwardingAppenderDisruptorEx?
    When I use RollingFileAppender only then I can achieve that using [%aspnet-request{HTTP_ASPFILTERSESSIONID}] in conversionPattern. But when I use this RollingFileAppender with AsyncForwardingAppenderHotSwapEx / AsyncForwardingAppenderDisruptorEx then ASP.NET session Id is not logged (probably because request related data is not fixed with logging event)...

    ReplyDelete