The Inquisitive Coder – Davy Brion's Blog

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.