Log4Net performance

Question

I have written a C# app that runs constantly in a loop and several threads write to a log4net file.

The issue is that the longer the app is running, the more time it takes to complete a loop. I have run a ANTS Performance profiler, and noticed that most of this CPU time is spent logging with log4.net.

The more verbose the logs the more CPU it uses and after 30 minutes its using 100% of the CPU. If I disable logging the time taken for a loop remains constant over time. I had a look at Windows Performance Monitor and the Physical Disk is most of the time IDLE.

I have tried to keep my logging to a minimum, but even with relatively low amounts of logging im still experiencing the issue.

Here is a sample of my Log4net.xml configuration file:

<log4net>
  <root>
    <!-- Levels: OFF, DEBUG, INFO, WARN, ERROR, FATAL-->
    <level value="INFO" />
    <appender-ref ref="RollingLogFileAppender" />
  </root>

  <!--Logs to a file-->
  <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="c:\\logs\\log-file.txt" />
    <appendToFile value="true" />
    <lockingModel type="log4net.Appender.FileAppender+ExclusiveLock" />
    <rollingStyle value="Composite" />
    <datePattern value="yyyyMMdd" />
    <maxSizeRollBackups value="20" />
    <maximumFileSize value="1MB" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level %logger %L %M Schdl:[%property{scheduleContext}] Job:[%property{jobContext}] - %message%newline" />
    </layout>
  </appender>
</log4net>

I am using the same logger from every object that logs.

  log4net.ILog logger;
  log4net.Config.BasicConfigurator.Configure();
  logger = log4net.LogManager.GetLogger(typeof(myProject));

Why would it use more and more CPU the longer it runs ?

Any advise on how to improve this would be appreciated.

Answer 1

Are you configuring log4net in every object that logs? It looks like that from your code. Configuration should be done once per process, e.g. at startup and then your objects should only have to acquire the logger.

For each class that needs to log I usually have the following pattern:

class SomeClass
{
    private static readonly ILog log = LogManager.GetLogger(typeof(SomeClass));
    ...
}

Using this pattern you will automatically get loggers that are hierarchical according to the namespace and name of the class.

Answer 2

(I have never used log4net before so take what I recommend with caution)

You could write an async proxy to log4Net component and log on a dedicated thread. You will no longer be blocking your main threads with attempts to write to the logfile.

This is all useless if log4net already has an async proxy.

Answer 3

What are you doing with those Context Properties? Schdl:[%property{scheduleContext}] Job:[%property{jobContext}] If you assign something more than just a value here (or an object with a simple ToString() method), it can bog down performance. See the log4net manual under Active Property Values for an idea of what I'm talking about.

Peter Lillevold has a good suggestion about configuring log4net only once. You can also put the following line in your AssemblyInfo.cs file:

[assembly: log4net.Config.XmlConfigurator()]

The following line is easy to cut and paste into any class that does logging:

private static readonly log4net.ILog _log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

You also might try turning on log4net internal logging to see what's going on:

  <appSettings>
    <add key="log4net.Internal.Debug" value="true"/>
  </appSettings>