NHibernate Profiler Review
Posted by Davy Brion on January 4th, 2009
A Profiler For NHibernate? What’s The Point?
If you’re not very experienced with NHibernate, it’s not always clear what NHibernate is doing behind the scenes. What kind of queries is it generating? How many entities are we loading? How often does it go the database? Even experienced NHibernate users can make mistakes which may result in inefficient data access, high memory usage, slow response times, etc. When used properly however, you can get excellent performance out of NHibernate.
According to the website, NHibernate Profiler delivers the following advantages:
- Cognitive application awareness
- Visual insight into the interaction between your database and application code
- Analysis and detection of common pitfalls when using NHibernate
- Analysis is delivered via perfectly styled SQL and linkable code execution
Sounds pretty good, right? Let’s take a closer look.
What is NHibernate Doing?
To get a good view on what NHibernate is doing, you should get answers to questions like:
- How many statements are we sending to the database?
- What statements are we sending to the database?
- What data are we loading into memory?
NHibernate Profiler makes it easy to anser those questions. For an NHibernate session where we send a simple query to the database, the profiler already gives us some useful information:

In the Statements tab, you get an overview of all of the statements in this session. When you select one of the statements, you can view more details in the tabs on the bottom. In this screenshot, you see a properly formatted SQL query which is the query that was generated by NHibernate. The overview also shows how many rows were retrieved by the query.
So we know how many entities were loaded, but which ones were they? Again, the profiler gives us some useful information on that:

The Entities tab shows you the identifiers of each entity instance (grouped by type) that was retrieved in the session. There’s also a useful general overview of your session usage:

Looks like the profiler is already alerting us of a possible problem. Let’s go the Alerts tab:

You can see the alert right there, with a link to a help page on the profiler’s website with a more detailed explanation. The help pages are very helpful and always suggest a way to avoid the problem. In this case, the problem is that our query returns the rows of a table without limiting the number of rows to be returned. In some cases, this can really be a problem but if you’re really sure that the table will always have just a few records then it’s not really a problem. A helpful extra feature here would be to mark the alert with some sort of “i know about this, and i don’t consider it a problem” action so it is removed from the profiler’s output. This specific alert can be disabled altogether as well, although i think it would be more useful to remove these alerts on a case-by-case basis.
Now, we know what NHibernate is doing which is pretty useful, but we also need an easy way to figure out which piece of code caused the SQL statements to be sent to the database. The profiler allows you to look at a stacktrace when you select a statement:

You can double click at each entry in the stacktrace and Visual Studio will show you that line of source code.
I think it’s clear that the profiler does a good job of showing you what NHibernate is doing behind the scenes. The output that the profiler is showing you is very useful as well:

This is the output of a batch of queries. Notice how the queries are nicely separated, and that the parameter values are already filled in. You can easily copy these select statements to execute the queries in whatever querying tool you’d like to use so you can study the actual output of a query. Another nice extra feature would be the ability to select a statement and have the profiler execute it against the database and showing you the results in a separate window.
I hope to see more information regarding the usage of NHibernate’s 2nd Level Cache in a future version of this profiler. It would be great to see which entity instances are stored in the cache, when they are stored and through which query, when they are retrieved from the cache instead of the database, when they expire from the cache, when they get refreshed, etc…
What are YOU doing?
Alright, we already covered how the profiler shows what NHibernate is doing. That’s nice. But do you know what you’re doing? Are you sure you’re using NHibernate properly? The profiler has a couple of nice features to warn you from mistakes you might make. As you saw earlier in this review, the profiler alerts you when you do something that might be problematic.
The profiler currently has the ability to alert you of the following problems:
- Select N + 1
- Too many database calls in a session
- Unbounded result set
- Excessive number of rows
- Usage of implicit transactions
- Large number of writes
The profiler offers guidance for each type of alert, making it clear how you can avoid the problem by suggesting other approaches. This guidance is offered through the website of the profiler (the application provides links), but it might be a nice idea to show that guidance from within the tool as well.
Here’s an example of the Select N + 1 problem:

As you can see here, the same query is executed 4 times with an ID parameter that differs each time. Naturally, it would be much better if this data was fetched in one query instead of 4. The profiler clearly alerts you to the problem, and through the stacktrace tab you can very easily navigate to the part of code that is causing the problem.
It’s also worth pointing out that you can modify the settings which trigger these alerts:

Overview Features
Looking at what each individual session is doing is useful, but sometimes you kind of want an overview of the overall NHibernate usage of your application. NHibernate Profiler offers 4 extra views on what’s going on in your application.
The first is an overview of all of the queries that were executed during the run:

This is useful, but i think it would be better if the grid included the average duration for each query. Also, a way to navigate from one of the queries to where it is triggered in code would be great here.
There’s also an overview of the queries that were triggered by class and method:

In this view it would also be very useful to show more information about average durations of statements.
The third one is a general overview of your overall NHibernate usage:

This one is very nice… the aggregated alerts pane is great, but when you click on the links next to the alerts a browser window will open with relevant alert information from the profiler’s website. I think it might be easier if you could just navigate from these aggregated alerts to the specific sessions which are causing these. For instance, if i have a SELECT N + 1 alert in there, i would like to have a way to go to the data from that specific session (or the sessions) with as little clicks and searching as possible.
The aggregated entities and the general statistics are also a very nice touch.
And finally, you can also keep track of the stats that NHibernate itself provides:

Conclusions
I’ve been playing with this profiler for a couple of weeks now, and i definitely like it a lot. It not only does a great job of quickly pinpointing problems, it also does a good job of teaching users how to properly use NHibernate. It not only saves you time when you need to fix a problem, it enables you to fix the problem in an informed manner. It’s got some great features already, and there will probably be many more interesting additions to the profiler in the future. Is this profiler worth the cost of the license? I’d say it definitely is. Not just for the time you’ll save because of it, but also for the stuff you’ll learn from it.
January 4th, 2009 at 10:19 pm
Looks very good!
Whenever you face performance problems it’s almost always improper database usage, so this surely looks like a promising addition to any serious (nhibernate using) developer’s toolkit.
How do you ’start profiling’? Is it dotTrace style of attaching to a process?
Also, is this all realtime or do you record your scenario first?
January 4th, 2009 at 10:20 pm
Also, i second your motion about more statistics regarding time spent, percentage of time relative to total time, etc. Those are musts for any serious profiler.
January 4th, 2009 at 10:24 pm
starting the profiler is explained here:
http://nhprof.com/Learn/GettingStarted
i’m not sure if it’s possible to do dotTrace-like attaching to make it all work, but that would be very cool
and yes, you get all of that data in real time. You can also save the data so you can view it at a later time though.
January 6th, 2009 at 1:43 am
Very interesting. I have recently been working on learning NHibernate by using it in a new pet project. Long way to go yet, but I can see the utility of such a tool to keep track of what an external (being external to your own code, that is) library is doing.
Is this tool the type that needs to be installed on a developer’s system, or can it be added to source control with the project like other tools, such as NHibernate itself?
January 6th, 2009 at 7:19 am
it requires no installation (so far) so you can just add it to the project’s repository
January 12th, 2009 at 3:15 pm
Wow, looks awesome. I am using NHibernate myself, I plan on attaching this and checking it out.
September 18th, 2009 at 4:33 pm
I changed the port number on the settings options from 22897 to port 80 and now profiler cannot even start up, it throws an error, so where are the settings stored when you change them so I manually change the value back to 22897?
September 19th, 2009 at 11:34 am
@Renso
you’re better off asking those kind of questions in the nhprof mailinglist:
http://groups.google.com/group/nhprof