NHibernate log4net 性能问题 - 如何禁用？

Question

我正在对我们的ASP .NET应用程序进行性能分析，以尝试减少CPU使用率，并发现NHibernate和log4net存在一些奇怪的行为。

我们应用程序中超过50%的时间都花费在log4net的GetLogger和CreateRepository方法上，这些方法是从NHibernate的ExecuteReader中调用的。下面的截图是JetBrains dottrace热点分析，箭头指向一个调用方法到被调用方法。

下面的截图只是最慢函数的列表。正如您所看到的，NHybridDataReader构造函数调用了GetLogger，而且需要很长时间。

显然有些可疑的事情正在发生，我想在NHibernate中完全禁用log4net，因为我们使用其他日志记录功能。

我们的web.config没有任何关于log4net的条目，那么我该如何禁用它呢？没有生成任何日志文件，并且从方法名称来看，它实际上还没有记录任何内容，而只是试图找到应该写入内容的记录器。

非常困惑，请问有人可以帮忙吗？

- Robin Weston

---

你正在运行3529个查询吗？这是有意为之还是无意的呢？（例如，意外的N+1） - Mauricio Scheffer

是的，这是有意的。这些截图来自生产环境。 - Robin Weston

你是否测量了每个查询的单独时间（即仅运行查询而不使用NHibernate）？这是确定NH / log4net是否真正具有重大开销所必需的。你的查询是什么样子的？ - Mauricio Scheffer

Answer 1

要回答您的具体问题（关闭NHibernate使用log4net），请查看NHibernate的Logging.cs文件中的代码。当我查看它时（虽然我看的是3.0 alpha代码，但我不认为它与2.x有很大区别），在静态LoggerProvider构造函数中，它委托GetNHibernateLoggerClass来确定要使用的类。如果它没有得到一个，它将使用基于no-op的类。因此，如果您查看GetNHibernateLoggerClass方法，您会发现它首先查找一个名为“nhibernate-logger”的appsettings键，您应该能够将其设置为“NHibernate.NoLoggingLoggerFactory，NHibernate”。您还可能注意到，如果缺少定义的键，则它将自动使用log4net，如果它在搜索路径中找到log4net DLL（可能只是包含NHibernate DLL的目录）。因此，您也可以尝试删除log4net DLL本身并查看发生了什么。虽然第一个解决方案更明确，第二个解决方案更为推断，所以我会使用第一个。

顺便说一句，这是开源工作得非常好的一个很好的例子。能够仅通过查看源代码来回答这样的问题。在闭源中，您要么必须欺骗和.NET反射器代码（可能已被混淆），要么祈求所有者大量记录像这样的晦涩点。

顺便说一下，这个同样的源代码文件提供了如果您想要将NHibernate的日志消息重定向到自己的日志记录解决方案所需的内容，正如您提到的那样（实现ILogger和ILoggerFactory接口并使用配置设置）。

- Rich

---

非常感谢您提供的这些信息。它对性能有很大的影响。再次感谢。 - pero

可能只适用于较新的版本，但是这段代码对我来说是有效的：LoggerProvider.SetLoggersFactory(new NoLoggingLoggerFactory()); - itsho

Answer 2

据我所见，您发布的截图显示时间实际上是花费在NHibernate运行某些查询上的。log4net与此无关。真正的问题是您似乎执行了3529次查询。

- Mauricio Scheffer

---

抱歉，我认为屏幕截图有误导性，将发布另一种JetBrains视图类型以使其更清晰。时间明确花费在log4net上。 - Robin Weston

@Robin：你应该按照“自己的时间”列进行排序，而不是其他时间列。 - Mauricio Scheffer

虽然“时间”包括在方法及方法调用中所花费的时间，但事实是，如果你查看代码，NHybridDataReader构造函数非常简洁。初始化程序获取记录器并分配变量。 - Rich

@Robin：如果你所说的是真的，那么静态方法LoggerProvider.LoggerFor应该会花费大量时间。请展示所有调用中该方法的截图。 - Rich

Answer 3

在您的配置文件中适当地设置NHibernate记录器的日志级别：

<logger name="NHibernate">
  <level value="ERROR" />
</logger>

我相信它默认为DEBUG并且会记录很多日志。我不建议完全禁用它，因为您希望被通知ERROR或FATAL事件。

- Jamie Ide

---

如果您没有指定日志记录器输出（就像我们所做的那样），这会有任何影响吗？ - Robin Weston

我认为它会，但我不确定。 - Jamie Ide