First Look At NHibernate Profiler

Ayende has released his NHibernate Profiler into private beta and i was lucky enough to be able to play around with it.

There’s no installer, so it’s just xcopy deployment. I don’t really like installers so the xcopy deployment is actually a plus in my book. I just put the files into an NH-Prof folder and that was that. Using it in a project currently requires adding a reference to one of the profiler’s assemblies and then adding the following line of code in your application’s startup routine:

            HibernatingRhinos.NHibernate.Profiler.Appender.NHibernateProfiler.Initialize();

After that, you simply start the client and run your application. As soon as NHibernate does something, you can see the results immediately in the profiler:

My test application immediately sends 2 queries in a MultiCriteria batch which is correctly picked up by the profiler as one statement. It also immediately alerts me that i executed those queries outside of a transaction. Pretty nice.

The profiler also can give you more information on the number of entities that were loaded in a session, and it can also show you which entities where loaded. But it looks like there’s still a bug there:

As you can see from the SessionFactory statistics, we’ve loaded 37 entities. Now, the SessionFactory statistics keeps statistics for all Sessions it created, but it also clearly shows that there has only been one used Session so far. The profiler however says that there were no entities loaded in this session:

In my second Session in the application, i use one query to retrieve the entities of 3 different classes. You can easily get NHibernate to print the SQL statements it generates, but they are not formatted so they’re not always very readable. This profiler makes the generated statements a lot easier to read:

But now that i’ve executed my second Session, i can suddenly see the entity details of the first Session:

The SessionFactory’s statistics show that we’ve already loaded 151 entities, and 37 of those were actually loaded in the first session. Those 37 entities are shown in the details of the second session however and i have no idea which entities where loaded in the second Session. Hopefully it’s an easy bug to fix because this is a piece of functionality that looks very useful for troubleshooting.

Another thing i like a lot is how the profiler properly replaces parameter values in the formatted queries:

Now you can easily just copy/paste the formatted query and execute it in whatever tool you prefer to see the actual output of queries.

Now, as you could see, there was a query where i used joins to combine the result of 3 different tables. If i would rewrite the code so i don’t use the joins and simply rely on NHibernate’s lazy loading to fetch the related data, the profiler would show me something like this:

As you can see, the profiler detects the notorious SELECT N+1 problem which is a very common mistake that a lot of people make with ORMs, or generated DALs for that matter. But wait, it gets better:

It also notifies you when you send too many queries in a Session! Very neat stuff.

I’ve only used the NHibernate Profiler on a small test application and i’m already pretty impressed. In the next couple of days i’m going to experiment with it on a real application and then i’ll post some more feedback on it.