Foolishness with NHibernate

Recently I've been working extensively on a web application based on ASP.NET with a C# backend. For data persistence I used Castle ActiveRecord, which is based on NHibernate. I encountered a problem with queries taking too long, or so I thought.

I wrote a bit of code that printed the amount of queries executed on the bottom of each page. I did that by putting a memory appender in my log4net settings.
By doing this, all SQL queries will be logged into the memory appender. At the end of each request I would simply get the amount of entries from the memory appender and clear it, like this:

        var app = Array.Find(LogManager.GetRepository().GetAppenders(), a => a is MemoryAppender) as MemoryAppender;
        if (app == null) return 0;
        var count = app.GetEvents().Length;
        app.Clear();

Using count as the number of queries, I was able to see how many queries NHibernate executed. To my amazement, it wasn´t all that much (10 queries max, which was acceptable for the situation).

My next step was to profile the database. I used a free SQLProfiler, which worked like a charm. However, none of the queries was causing a lot of problems. I did manage to fix some small performance issues (the mappings weren't written very carefully, so there were a lot of useless joins done. Lazy loading is a blessing!), but it still didn't solve my problem.

I eventually found the problem. I had a root logger configured for log4net, which meant every single logmessage was getting written to an appender. After removing the appender, everything was as fast as it was supposed to. The hardest problems are sometimes so easy to fix that you won't find the solution until you exhausted every other option...

So, if you're planning to use NHibernate in a production environment, be very careful with your logging settings!