Yesterday my boss and I meet with a group that has been having some significant performance issues with one of their web applications.

It’s a basic .Net web forms application (in C#). Their issue was that they had one page that was taking upwards of 75 seconds to load! Seriously. 75 seconds! They said they were using NHibernate and they had tracked the issue down to one method that was taking up the majority of those 75 seconds. They also said they had tried some direct database (Oracle) queries that returned MUCH faster than the NHibernate.

We suggested that they look at caching the results of the database queries and that they confirm exactly what queries NHibernate is making on their behalf (I think they assumed it would execute the same query they had tested directly, which may or may not be the case).

Now I am a fan of NHibernate, and I have done some things with it that resulted in less than stellar performance, but I’ve always found tweak things to near direct database performance levels without much effort by changing/correcting some basic assumptions I had about the data and model. So when I left the meeting I felt that NHibernate had unfairly been labelled as the source of the performance issues, so I decided to have a look at the code for myself.

After grabbing a local copy of the code from their source control repository, I ran the code in debug mode and quickly came to the conclusion that the method they had identified as taking a long time to execute was in fact really taking a long time to execute. So I had a closer look at that method, and here (essentially) is what I saw:

/* ... */
IQuery query = CreateQuery("SELECT ...");

for (i = 0; i < query.List().Count; i++)
{
    if ((!((object[])(new ArrayList(query.List())[i]))[0] == null)
       && (!((object[])(new ArrayList(query.List())[i]))[2] == null))
    {
        String value = (((object[])(new ArrayList(query.List())))[2]).ToString();
    }
}
/* ... */

I am “paraphrasing” a bit (the real code was worse).

The query.List() call returns an IList instance containing all the results of the SQL query. I don’t know if each call to query.List() actually executes the database query again (there may be some caching involved somewhere) but each call to query.List() did involve some database activity (according to my network sniffer). You notice that query.List is being called 3 times per loop (in the real code it was more like 6 times per loop)!

Changing this code to make one call to query.List, storing the results in a local IList variable and subsequently re-using that local variable shaved nearly 50 seconds of the response time.

On top of that there would also be improvements by removing the code that creates 3 ArrayLists per loop (again in the real code, 6 ArrayLists per loop), copies the IList of database results into each ArrayList, uses each of those ArrayLists to access only one single item and them discards the ArrayLists (only to recreate them again on the next loop).

NHibernate wasn’t the source of their problem…