NHibernate log4net performance problem - how to disable?

Question

I was profiling our ASP .NET application to try and reduce the CPU usage and fond some strange behaviour regarding NHibernate and log4net.

Over 50% of the time on our app is spent in the log4net GetLogger and CreateRepository methods, which are called from ExecuteReader in NHibernate. The screenshot below is a jetBrains dottrace hotspot analysis where the arrows point from a calling method to the called method.

The below screenshot is just a straight up list of slowest functions.As you can see the NHybridDataReader constructor calls GetLogger and it takes ages.

Clearly something fishy is going on, and I want to disable log4net completely in NHibernate as we use other logging functionality.

Our web.config has no entries in it regarding log4net, so how do I disable it? There are no log files being produced, and from the look of the method names, it hasn't actually got round to logging anything, but is merely trying to find the logger it should write stuff to.

Most confusing, can anyone help?

Answer 1

As I see it, the screenshot you posted says that the time is actually spent on NHibernate running some query. log4net has nothing to do here. The real problem is that you seem to be executing some query 3529 times.

Answer 2

For an answer to your specific question (turning off use of log4net by NHibernate), look into the code the Logging.cs file for NHibernate. When I looked at it (granted, I looked at 3.0 alpha code, but I doubt it's much different than 2.x), in the static LoggerProvider constructor, it delegates to GetNHibernateLoggerClass to determine the class to utilize. If it doesn't get one, it uses a no-op based class. So if you look in the GetNHibernateLoggerClass method, you see that it first looks for an appsettings key called "nhibernate-logger", which you should be able to set to "NHibernate.NoLoggingLoggerFactory, NHibernate". You may also notice that lacking a defined key, it will automatically use log4net if it finds the log4net DLL in the search path (likely just the directory containing NHibernate DLL. So you may also want to try removing the log4net DLL itself and see what happens. Though the first solution is more explicit and the second more is more inferred, so I would use the first.

As a side note, this is a great example of why open source works so well. Being able to just look thru the source code to answer a question like this. In closed source, you'd either have to cheat and .NET reflector the code (which could be obfuscated), or pray that the owners heavily documented obscure points like this one.

BTW, this same source code file provides what would need if you want to take NHibernate's log messages and redirect them to your own logging solution, as you mentioned you had (implement the ILogger and ILoggerFactory interfaces and use the config setting).

Answer 3

Set the logging level approproately for the NHibernate logger in your config file:

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

I believe it defaults to DEBUG and it does a lot of logging. I would not disable it entirely since you want to be informed of ERROR or FATAL events.