Log4Net.Async slower than regular RollingFileAppender

[sklose]

I did some benchmarking and noticed that both asynchronous forwarders provided by this library are significantly slower than using the regular RollingFileAppender. Here is the benchmark:

  <log4net>
    <appender name="file" type="log4net.Appender.RollingFileAppender">
      <param name="File" value="C:\Log\Test.log" />
      <param name="AppendToFile" value="true" />
      <param name="RollingStyle" value="Date" />
      <param name="DatePattern" value=".yyyy-MM-dd" />
      <param name="MaxSizeRollBackups" value="10" />
      <param name="MaximumFileSize" value="5120000" />
      <param name="StaticLogFileName" value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
      </layout>
    </appender>
    <appender name="fwd1" type="Log4Net.Async.ParallelForwardingAppender,Log4Net.Async">
      <appender-ref ref="file" />
      <bufferSize value="1000000" />
    </appender>
    <appender name="fwd2" type="Log4Net.Async.AsyncForwardingAppender,Log4Net.Async">
      <appender-ref ref="file" />
      <bufferSize value="1000000" />
    </appender>
    <logger name="RFA">
      <level value="DEBUG" />
      <appender-ref ref="file" />
    </logger>
    <logger name="BC">
      <level value="DEBUG" />
      <appender-ref ref="fwd1" />
    </logger>
    <logger name="RB">
      <level value="DEBUG" />
      <appender-ref ref="fwd2" />
    </logger>
  </log4net>

    class Program
    {
        static void Main(string[] args)
        {
            XmlConfigurator.Configure();
            foreach (var name in new[] {"RFA", "BC", "RB"})
            {
                var logger = LogManager.GetLogger(name);
                var sw = Stopwatch.StartNew();
                for (int i = 0; i < 10000; i++)
                {
                    logger.Info("Replace this placeholder with a long string");
                }
                sw.Stop();

                Console.WriteLine($"{name} Seq: {sw.Elapsed}");

                sw = Stopwatch.StartNew();
                Parallel.For(0, 10000, i =>
                {
                    logger.Info("Replace this placeholder with a long string");
                });
                sw.Stop();

                Console.WriteLine($"{name} Parallel: {sw.Elapsed}");
            }

            Console.ReadLine();
        }
    }

And the result is

Logger	Single Thread / Multi Thread	Time
Rolling File Appender	Sequential	389ms
Rolling File Appender	Parallel	751ms
Blocking Collection	Sequential	1865ms
Blocking Collection	Parallel	4689ms
Ring Buffer	Sequential	1800ms
Ring Buffer	Parallel	5433ms

The culprit is the FixFlags setting in AsyncForwardingAppenderBase. If I exclude FixFlags.Properties it it's roughly 2x faster than the RollingFileAppender. I tried overwriting the FixFlags in my XML configuration, but that results in a NullReferenceException.

[rcollette]

Good catch. If it suits your needs, ParallelForwardingAppender is a newer implementation and uses non-default fix as in your PR. I suspect that there is a way the buffer implementation could be abstracted such that ParallelForwardingAppender could use either a blocking buffer or a ring buffer. This would allow us to deprecate and eventually remove AsyncParallelForwardingAppender.

[cjbhaines]

Fix flags can now be set. Thanks for the PR.