log4net 性能问题：消息之间的固定延迟

Question

我有一个相当复杂的应用程序，它由 2 个网站和 3 个 Windows 服务组成。都使用相同的log4net配置，只是写入不同的文件：

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

但一个站点存在写入日志的巨大性能问题 - 每两条相邻的消息之间或多或少都有固定延迟。例如，这是我的日志文件的一部分：

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

如您所见，即使仅记录对象的属性（没有复杂的逻辑来检索它们），延迟也超过 300 毫秒。我发现此延迟与日志大小成正比：如果是 1 MB，则延迟约为 100 毫秒、2 MB - 200 毫秒、3 MB - 300 毫秒。我想知道什么会导致这样的问题。任何想法都会受到高度赞赏。

调查详情：

由于我们没有直接使用 log4net，而是创建了一个包装器，我首先认为包装器中有一个错误，但它很简单，我不知道它是如何只在一个站点中引起如此奇怪的问题。

VS 2013 性能分析器 令人惊讶的是，它并没有说记录器方法占用的样本最多（我使用了采样分析）。我认为这证明问题不在于逻辑，而在于访问外部资源，而应用程序线程被挂起。

我没有发现两个站点之间存在任何差异，这应该会在一个站点中导致此问题并在另一个站点中找到。当然，这些站点非常不同，但没有可疑的环境或 IIS 配置差异。

我有一个想法，即在每次写入时打开和关闭日志文件，但我不知道如何确定。我可以在记事本中打开日志，在应用程序运行时对其进行编辑和保存。大概这就是一个证明。但是在这种情况下，延迟不应该与文件大小几乎固定（不成比例）吗？系统所需要的只是寻找由文件大小定义的文件的末尾（如果文件被分区，可能很少寻找，但这并不重要）。如果这是问题，我该如何解决？我尝试使用缓冲日志附加器，但结果相同。

其他想法是防病毒软件在每次写入时检查文件，但禁用它并没有解决问题。

更新：

将日志文件夹从本地相对路径更改为其他目录“D:\Logs...”解决了我的开发环境中的问题，但在测试机上不起作用。

更新 2

问题是复制不稳定。有一天，我可能会遇到所描述的性能问题，并且重新启动或更改日志配置都没有帮助；但是有一天问题消失了，我想我找到了解决方案。但是现在它又开始复制了，我不知道为什么会这样。

Answer 1

很难诊断这类问题，因为可能有许多因素在起作用来解释差异。但是你提到你有很多伐木演员。他们都在同一台机器上吗？您发布的配置文件是针对有问题的站点的配置文件吗？

这不是您问题的直接答案，但您也可以调查 BufferingForwardAppender (example)，它会累积消息直到配置的限制。这不会直接解决问题，但会在您的日志文件上增加“写作税”，并且它具有一些有趣的属性（例如有损日志记录，但这不是主题:)）