views:

349

answers:

3

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.

+9  A: 

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.

Peter Lillevold
Right, and every object that logs can access the logger: `private static readonly ILog log = LogManager.GetLogger(typeof(MyProject));`
Jamie Ide
You are right, I was running Configure() in each object that logs. I have added the static member to each logger object. So far so good. I will perform more tests and update after this.
Benjamin Ortuzar
Thanks @Jamie, this is how I do it too unless I'm using dependency injection.
Peter Lillevold
After removing the extra Configure() I am able to stably log for hours, I am also able to log much bigger amounts of text without the performance issues I was experiencing. Thanks for your help.
Benjamin Ortuzar
Great, glad to be of assistance!
Peter Lillevold
A: 

(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.

Gord
+3  A: 

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>
Im using the context properties to specify the IDs of the Job and Schedule, both are Int32. They make it easier for me to filter the log. If this numbers generate a performance issue i could add this variables to the log message.
Benjamin Ortuzar
I use properties like that from fairly busy ASP.NET sites (multiple threads logging to one FileAppender) without problems. Simple values shouldn't be the problem.