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!
Comments 4
If your theory is correct, why did the problem persist when you changed the log level to WARN?
Posted 12 Sep 2008 at 7:41 pm ¶Damn you and your logic.
Without looking at the log4net and NHibernate source, anything I conclude will be purely speculative; however, something must require those permissions and that something must be the root of my performance issues.
Curiosity is trying to get me to dig into the source, but down this road madness lies.
Posted 12 Sep 2008 at 9:37 pm ¶Log4net (what nhibernate uses) is a non guarenteed service so they do some exception handling and then throw away the exeption. But I think the reason why it slows down is that it takes more time to determine that you can’t write then it takes to write to a file. Just a guess though. Like it takes more time to determine a site is not available. it probably tries several times to write to it and then gives up. Interesting. (sorry if i don’t make sense ;-))
Posted 20 Sep 2008 at 5:36 pm ¶In addition, the same exception could be thrown during WARN and DEBUG modes… Not being overly familiar with the source of these projects I couldn’t say one way or the other, but the DEBUG and WARN configs may not actually make a difference in the scenario you described…
Posted 02 Oct 2008 at 12:14 am ¶Post a Comment