NHibernate Was Painfully Slow, So Naturally I Thought Log4Net Must Be The Problem

This is a cautionary tale, a what not to do when faced with a bug comes and goes and seems intractable.

We are working on a customer project with an O/RM persistence layer. We're using NHibernate, and up until recently, it's been a joy to work with. I say recently, because about a week ago, our project started to load from and save to the database in an increasingly slow fashion.

I mean, painfully, mind-numbingly, bang-your-keyboard-ingly slow. 30 seconds to save 100 records. Multiple minutes to load them back from the database on startup.

And worse, the problem would come and go. It was constant our main application, but inconsistent on the test application that we use to implement and test out some new features. I was having a lot of difficulty trying to isolate the symptoms of the issue, and get to the root cause.

Now, did I do what smart developers do? Sit back and think of what had changed? Talk to my development team partner in our scrum meeting about what was holding me back? Did I pair-program through the issue? Did I RTFM? No, I did not. Because I am both obtuse and stubborn.

Instead, I did all of the following:

• Upgraded from NHibernate 1.2 to 2.0 (that's not so bad, we had to do it anyway for another aspect of the project)
• Went down a long tangent with lazy-loading
• Attempted to speed up the load from the DB using HQL
• .. and so on

Finally I caught two breaks. One, I isolated how the test program was failing. And two, Jamie said "Hey, you know that NHibernate is dumping lots of stuff to the new logging I implemented, right?"

Jamie had implemented Log4Net to log exceptions on stuff that we couldn't parse. And it turns out, if you turn on Log4Net, NHibernate will happily use it. A fact that I should have realised, considering it was me who said, "Jamie, if you're going to use log4net, grab the one out of the NHibernate distribution." But I digress. The point is that Log4Net is application wide, and if you set up your application to print out DEBUG level warnings, you get a lot of stuff from NHibernate. Like 100 meg log files, and file I/O on every call to the database as it writes out the SQL it just used. Which will make stuff run 30 to 100 times slower than it should.

So, don't be like me. Think about the problem first. RTFM. Talk to your team about what's changed. And if you turn on debugging in Log4Net, turn it off for NHibernate using the configuration files found in the last post on this thread.