log4net performance issue: fixed delay between messages

Question

I have quite complex application which consist of 2 web sites and 3 windows services. All use same log4net configuration, just write into different files:

<log4net>
  <logger name="Default">
    <appender-ref ref="VerboseLogFileAppendder" />
  </logger>
  <appender name="VerboseLogFileAppendder" type="log4net.Appender.RollingFileAppender">
    <threshold value="DEBUG" />
    <file value="Logs\MyProductName" />
    <appendToFile value="true" />
    <rollingStyle value="Date" />
    <maximumFileSize value="100MB" />
    <datePattern value="'.'yyyy-MM-dd'.log'" />
    <staticLogFileName value="false" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%-3thread] %-5level - %message%newline" />
    </layout>
  </appender>
</log4net>

But one site has huge performance issues with writing logs - every two adjacent messages has more or less fixed delay between them. For example, here is part of my log file:

2014-03-21 21:48:19,163 [24 ] INFO  -       Begin SiteColourTheme
2014-03-21 21:48:19,489 [24 ] INFO  -         IsChanged = False
2014-03-21 21:48:19,808 [24 ] INFO  -         GridHeaderColour.BackgroundColour = #373F71
2014-03-21 21:48:20,133 [24 ] INFO  -         GridHeaderColour.IsBackgroundColourChanged = False
2014-03-21 21:48:20,464 [24 ] INFO  -         GridHeaderColour.FontColour = #E0E0E0
2014-03-21 21:48:20,800 [24 ] INFO  -         GridHeaderColour.IsFontColourChanged = False
2014-03-21 21:48:21,134 [24 ] INFO  -         GridHeaderColour.IsColourThemeChanged = False
2014-03-21 21:48:21,475 [24 ] INFO  -         DialogHeaderColour.BackgroundColour = #373F71
2014-03-21 21:48:21,810 [24 ] INFO  -         DialogHeaderColour.IsBackgroundColourChanged = False
2014-03-21 21:48:22,139 [24 ] INFO  -         DialogHeaderColour.FontColour = #FFFFFF
2014-03-21 21:48:22,462 [24 ] INFO  -         DialogHeaderColour.IsFontColourChanged = False
2014-03-21 21:48:22,781 [24 ] INFO  -         DialogHeaderColour.IsColourThemeChanged = False
2014-03-21 21:48:23,122 [24 ] INFO  -         AccordionPaneColour.BackgroundColour = #F8F8F8
2014-03-21 21:48:23,481 [24 ] INFO  -         AccordionPaneColour.IsBackgroundColourChanged = False
2014-03-21 21:48:23,862 [24 ] INFO  -         AccordionPaneColour.FontColour = #2B2B2B
2014-03-21 21:48:24,202 [24 ] INFO  -         AccordionPaneColour.IsFontColourChanged = False
2014-03-21 21:48:24,522 [24 ] INFO  -         AccordionPaneColour.IsColourThemeChanged = False
2014-03-21 21:48:24,862 [24 ] INFO  -         PageTabColour.BackgroundColour = #DCDBDB
2014-03-21 21:48:25,208 [24 ] INFO  -         PageTabColour.IsBackgroundColourChanged = False
2014-03-21 21:48:25,527 [24 ] INFO  -         PageTabColour.FontColour = #000000
2014-03-21 21:48:25,855 [24 ] INFO  -         PageTabColour.IsFontColourChanged = False

As you can see, the delay is more than 300ms even for just logging properties of an object (there is no complex logic to retrieve them). What I've discovered that this delay is proportional to the log size: if it is 1 MB, the delay is about 100ms, 2 MB - 200ms, 3 MB - 300ms. I wonder what could cause such problems. Any ideas would be highly apreciated.

INVESTIGATION DETAILS:

Since we are not using log4net directly, but created a wrapper, I first thought there is a bug in wrapper, but it is quite simple and I have no idea how it could cause so strange issues only in one site.

VS 2013 performance analyzer surprisingly didn't say that logger methods took the most samples (I used sampling analyze). I think it proves that issue is not in logic, but in access to external resources, while application thread is suspended.

I didn't find any difference between two sites that should cause this issue in one and work find in other. The sites are very different of course, but no suspicious environment or IIS configuration differences.

I had an idea that log file is opened and closed on each write, but I don't know how to check that for sure. I can open log in the notepad, edit and save it while application is running. Probably that may be a proof. But shouldn't the delay be almost fixed (not proportional) to file size in this case? All that system needs is seeking to the end of a file which is defined by file size (maybe few seeks if file is partitioned, but that's not important). If this is the problem, how can I fix it? I tried using buffered log appender, but same result.

Other idea was that antivirus checks file on each write, but disabling it didn't solve the problem.

UPDATE:

Changing logs folder from local relative path to other directory "D:\Logs..." solved the problem on my development environment, but didn't work on test machine.

UPDATE 2

The issue is reproducing not stabilly. One day I may have the described performance issue and neither restarts, or changing log configuration helps; but then someday the problem goes away and I thought I found a solution. But now it is again reproducing and I don't know why this is happening.

Answer 1

It's really hard to diagnose these kind of issues since many factors may be in play to explain the difference. However you mentioned that you had many logging actors. Are they all on the same machine? Is the configuration file you posted the one for the site with the problem?

It's not a direct answer to your question but you could also investigate the BufferingForwardAppender (example), which accumulates messages until a configured limit. This will not solve the problem directly but will compound the "writing tax" on your log file, and it has some interesting properties (lossy logging for example, but that's not the subject :) )