Asynchronous Log4Net Appenders

I have spent the majority of my time over the last week performance profiling an enterprise application using ANTS Performance Profile. The results showed that we were having huge delays (over a second) on Log4Net when under load, which I thought was strange as it’s such a tried and tested logging framework. After some digging through their source code it’s evident that requests are processed on the calling thread, bad news for this situation! We use an AdoNetAppender so the slowdown was probably due to database contention because it’s a multi threaded architecture and the large number of requests that were being processed. I didn’t expect the loggers to use blocking calls however that’s just the way things are. Due to this I have come up with a couple of Asynchronous wrappers which run a background thread to call the base Appender and queue up the log requests in a RingBuffer which has a size limit to avoid excessive memory usage. The full production ready source code including unit tests is available on GitHub here.

6 Thoughts on “Asynchronous Log4Net Appenders

  1. Linda Gouchie on July 29, 2013 at 9:39 pm said:

    Chris,
    Thanks for creating this component. It is exactly what we need. Am wondering how I can add custom properties to this. Previously we were using the threading.Context which works fine for the standard ado appender, but not for the asynchronous one. (Am assuming this is because our method is not thread-safe.) Can you recommend a different way to do this? I have about 10 additional custom properties that I need to write out asynchronously. Thanks in advance,

    Linda

  2. Chris Haines on August 1, 2013 at 10:13 pm said:

    Hi Linda,

    You can still use the thread static properties to do this, I have done something similar at Betgenius. If you create a copy of the LoggingEvent and then add the properties to the LoggingEvent before it get’s enqueued using the copy to the RingBuffer then you can still access all of the correct properties safely. The following link is doing something similar, however where he calls base.Append that is where the enqueue will happen. http://selectsoftwarethoughtsfromtyler.blogspot.co.uk/2006/09/adding-custom-logging-properties-to.html

    Here is a rough outline of what you should do:

    
            protected override void Append(LoggingEvent loggingEvent)
            {
                if (FilterEvent(loggingEvent))
                {
                    var loggingEventCopy = CopyLoggingEvent(loggingEvent);
                    SetThreadStaticProperties(loggingEventCopy);
                    pendingAppends.Enqueue(loggingEventCopy);
                }
            }
    

    Hope that helps.

    Cheers,
    Chris

  3. Any chance you could post some help on how to add this to an existing log4net configuration – like with an external config file and such?

    Chris

    • Chris Haines on August 19, 2013 at 9:53 pm said:

      Hi Chris, here is an example config section:

      
      <log4net debug="false">
          <appender name="rollingFile" type="AsynchronousLog4NetAppenders.AsynchronousRollingFileAppender,AsynchronousLog4NetAppenders">
            <file value="C:\Logs\ApplicationName.log" />
            <appendToFile value="true" />
            <threshold value="WARN" />
            <rollingStyle value="Size" />
            <maxSizeRollBackups value="10" />
            <maximumFileSize value="10MB" />
            <staticLogFileName value="true" />
            <layout type="log4net.Layout.PatternLayout,log4net">
              <param name="ConversionPattern" value="%utcdate|%-5level|%logger|%thread| %message %exception%n" />
            </layout>
          </appender>
          <appender name="adoNet" type="AsynchronousLog4NetAppenders.AsynchronousAdoAppender,AsynchronousLog4NetAppenders">
            <connectionType value="System.Data.SqlClient.SqlConnection, System.Data,Version=1.0.5000.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
            <connectionString value="CONNECTIONSTRING" />
            <commandText value="INSERT INTO Log4Net([Date], [Thread], [Level], [Logger], [Message], [Exception]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception)" />
            <ReconnectOnError value="true" />
            <parameter>
              <parameterName value="@log_date" />
              <dbType value="DateTime" />
              <layout type="log4net.Layout.RawUtcTimeStampLayout" />
            </parameter>
            <parameter>
              <parameterName value="@thread" />
              <dbType value="String" />
              <size value="255" />
              <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%thread" />
              </layout>
            </parameter>
            <parameter>
              <parameterName value="@log_level" />
              <dbType value="String" />
              <size value="50" />
              <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%level" />
              </layout>
            </parameter>
            <parameter>
              <parameterName value="@logger" />
              <dbType value="String" />
              <size value="255" />
              <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%logger" />
              </layout>
            </parameter>
            <parameter>
              <parameterName value="@message" />
              <dbType value="String" />
              <size value="4000" />
              <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%message" />
              </layout>
            </parameter>
            <parameter>
              <parameterName value="@exception" />
              <dbType value="String" />
              <size value="4000" />
              <layout type="log4net.Layout.ExceptionLayout" />
            </parameter>
          </appender>
          <root>
            <priority value="WARN" />
            <appender-ref ref="rollingFile" />
            <appender-ref ref="adoNet" />
          </root>
        </log4net>
      
  4. Simon Bernholtz on October 14, 2013 at 6:54 am said:

    Hi Chris,
    I found your “Asynchronous Log4Net Appenders” and i wanted to say thank you for sharing it.
    I just have a question if i may.
    Why did you not use one of the many Dataflow (Task Parallel Library) blocks available in .net 4 or .net 4.5
    instead of creating and maintaining your own buffer. Wouldn’t it be better to use an “ActionBlock” or a “BatchBlock” so that we don’t
    have to worry about Consumers/Producers issues?
    thank you in advance

    • Chris Haines on December 11, 2013 at 6:52 pm said:

      Hi Simon,

      Honestly I didn’t know that was available but after taking a look it doesn’t look like a good fit. Firstly everywhere you use Log4Net you will need to go through and add another NuGet reference as the System.Thread.Tasks.Dataflow assembly is not a standard framework dll (Betgenius has 100+ solutions, so that would be painful and these Appenders are in standard util libraries which we already reference). Secondly this would remove the need for the in memory buffer because all the logging actions would be queued up in the action block. This means that if you have a slow appender that is getting more requests than it can handle you will have memory bloating. The ring buffer allows us to swap out old messages for newer ones when the buffer limit is reached. I personally like to keep control over my threads, I dont know how the ActionBlock works in regards to releasing threads back to the ThreadPool when its idle so I would prefer to just hold a single thread and keep it permanently available for immediate work which keeps it efficient.

      Cheers,
      Chris

Leave a Reply

Your email address will not be published. Required fields are marked *

Please type the characters of this captcha image in the input box

Please type the characters of this captcha image in the input box

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>

Post Navigation