Empty NHibernate logs and poor performance

We had an issue recently where NHibernate was performing very poorly on our production server, but not on our developer machines or our test server. I investigated the issue and narrowed it down to two symptoms.

Symptom 1: Very poor performance. I’m talking 10+ seconds per page load, with no more than 5 queries being executed by NHibernate.

Symptom 2: Empty log files. None of our log files had any data in on the live server, but they did on our other systems.

I decided to investigate the second symptom first, as it may be causing the first (ends up it was).

Firstly, I noticed that our logging was set to DEBUG. Must’ve been a leftover from when we first deployed NHibernate, very sloppy, I know. So I reset that to WARN, but it had no effect.

When files aren’t being written to, you should always check the directory permissions. Low and behold, it was a permissions problem. Our test server had different users allowed to write to the Logs directory than our production server. I granted the same users access, NETWORK SERVICE and IUSR_MACHINENAME in our case.

After I recycled the IIS worker processes, we were flying again. We’re back to having < 1sec page loads.

This is pure speculation, but what I believe was happening is this: Logging was set to DEBUG, so it was logging a lot. With each log call, the logger was failing to get write access to the files and throwing an exception, that exception would probably have propagated a bit too. The combination of the sheer amount of data being written to the log, and an exception per log call, were responsible for the severe slowdown.

So in short: Always make sure NHibernate has write access to its own log directory!