Specialized NHibernate Profiler Demystifying Performance

If you use NHibernate in your code, this article is for you. Like most people, you probably wouldn’t go to the grocery store several times buying one item at a time. Why not just go once and buy them all? In the case of buying groceries it’s a no-brainer, but what about database accesses? Is it possible that we are unaware of costly and underperforming queries in our code? Yes, of course. Applications that use NHibernate often contain dozens of projects and simply have too many moving parts to effectively monitor their database interactions. Also, while NHibernate is very convenient to use, the abstraction it provides makes it hard to trace SQL server queries and identify inefficient ones.

For example, look at this trivial query:

// SELECT * FROM Posts
foreach (Post post in session.CreateQuery("from Post").List())
{
   // lazy loading of comments list causes: 
   // SELECT * FROM Comments where PostId = @p0
   foreach (Comment comment in post.Comments) 
   {
       //print comment...
   }
}

NHibernate code that loads all posts and comments of a blog.

This seemingly simple code hides the complexity of the operation, as it unfolds behind the scenes to an inefficient Select N+1 query. With potentially thousands of such queries in our code base, what are the odds that they are all well-optimized? And even if current performance is reasonable, can we tell how all these queries will perform once we scale the application or apply changes to the code? Probably not. Database interactions are especially prone to poor visibility and underperformance when the database layer is neglected by the developers, which is not uncommon.

Gain Visibility Into Your Application’s Database Interactions

Improving visibility and performance of database interactions calls for a specialized profiler. The desired profiler would not only alert when underperforming queries are executed, but could also provide valuable context, such as application activity and business actions relevant to each query. Indeed, lack of context is one of the reasons why developers are not satisfied with the database’s built-in profiler, which can also be complex to use and operate.

In general, the desired profiler should not just litter the report with a pile of queries, but rather organize the data and make it intelligible. For example, showing how many queries were used to generate a page is much more useful as a metric than just providing out-of-context information of each individual query. Using the grocery store analogy, the desired profiler would alert that making one cake took six visits to the store, providing context that can be applied to reduce store visits. In contrast, the built-in database profiler would only show that a lot of cake ingredients were bought, entirely missing the separate trips and their inherent latency.

Preferably, the alerts could also take the developer to the exact location in the code when clicked on. This feature is also not supported by built-in database profilers, which are aimed at DBAs rather than developers.

Screenshot

Valuable context: clickable statements that jump to the code they originated from.

Developers would also prefer a user-friendly GUI to ensure a short learning curve and high productivity. Essentially, the feature set and UI of the desired profiler should be designed for developers from the ground up, unlike the built-in database profiler.

One profiler that was created with developers in mind and provides all these features is the NHibernate Profiler by Hibernating Rhinos.

Screenshot

The NHibernate Profiler’s GUI and feature set have been designed for developers from the ground up.

Save on Azure Costs by Handling Expensive Queries

Moving the application to Azure has many benefits but it is not without downsides:

  • Database interactions now cost money and are subject to Azure’s pricing model.
  • Underperforming queries can introduce latency and damage the user experience.
  • The visibility into the database layer is greatly reduced when moving to the cloud.

Luckily, the NHibernate Profiler supports Azure profiling integration, allowing developers to profile their NHibernate queries from Azure Functions. Following a simple initialization of the profiler, profiling events can be uploaded as blobs to an Azure container. The profiler can then seamlessly integrate with the profiled application in a distributed fashion using the Azure Blob storage, and queries can be displayed in real-time.

Screenshot

Configuring the NHibernate Profiler to listen to the enqueued messages.

Optimization Recipes for Developers by the NHibernate Profiler

On top of providing alerts and insights, the NHibernate Profiler also guides how to optimize underperforming queries, as demonstrated below.

Select N+1

The NHibernate Profiler carefully examines select operations to detect suboptimal Select N+1 queries, which are notorious for being potential performance hogs.

This code, for example, lazy loads some blog posts and traverses their comments inefficiently, fetching the results one row at a time.

// SELECT * FROM Posts
foreach (Post post in session.CreateQuery("from Post").List())
{
   // lazy loading of comments list causes: 
   // SELECT * FROM Comments where PostId = @p0
   foreach (Comment comment in post.Comments) 
   {
       //print comment...
   }
}
Screenshot

This lazy loading causes an inefficient Select N+1 query and triggers the alert.

The lazy loading triggers an NHProfiler alert that suggests using eager loading instead. To refactor this code, developers can use HQL, Criteria API or Linq as follows:

var posts = session
    .CreateQuery("from Post p left join fetch p.Comments")
    .List();

Forcing eager loading using HQL.

session.CreateCriteria(typeof(Post))
    .SetFetchMode("Comments", FetchMode.Eager)
    .List();

Forcing eager loading using Criteria API.

var posts = (from post in session.Query<Post>().FetchMany(x => x.Comments) 
             select post).ToList();

Forcing eager loading using Linq.

Too many joins

The NHibernate Profiler alerts when detecting too many joins as each join loads the database with additional work, increasing the complexity and cost of the query and potentially creating Cartesian products.

select *
from Blogs blog0_
    inner join Posts posts1_
        on blog0_.Id = posts1_.BlogId
    inner join Comments comments2_
        on posts1_.Id = comments2_.PostId
    inner join Users user3_
        on posts1_.UserId = user3_.Id
    inner join UsersBlogs users4_
        on blog0_.Id = users4_.BlogId
    inner join Users user5_
        on users4_.UserId = user5_.Id
Screenshot

This query triggers the NHibernate Profiler’s “Too many joins” alert.

To remedy this, use several separate queries instead of a single query containing multiple joins.

A query on an unindexed column

Querying on an unindexed column forces the database to search through all the rows in the table. When encountering this alert, consider whether to create an index, modify the query, or dismiss the alert if the table is small enough to afford the scan.

Screenshot

A “Query on un-indexed column” alert provided by the NHibernate Profiler.

Unbounded results set

A query that does not explicitly limit the number of returned results can be a time bomb waiting to explode, and easily go undetected during development and testing. In production, however, a query with unbounded results set can return thousands and even millions of rows, overloading the database.

session.CreateQuery("from OrderLines lines where lines.Order.Id = :id")
       .SetParameter("id", orderId)
       .List();
Screenshot

An “Unbounded results set” alert is triggered here.

Consider the query above, for example. If the order has too many line items, they will all be loaded, which is probably not what was intended. This can be easily fixed using the SetMaxResults method that allows pagination, as demonstrated below.

session.CreateQuery("from OrderLines lines where lines.Order.Id = :id")
    .SetParameter("id", orderId)
    .SetFirstResult(0)
    .SetMaxResults(25)
    .List();

The results set is limited to 25 posts using the SetMaxResults method.

The actual code change to fix the issue is trivial, but bringing it to the developer’s attention is where the NHibernate Profiler truly shines. Instead of starting from a slow application and an investigative process that often involves multiple parties each using their own tools, developers can get an immediate answer pinpointing the exact line of code that needs to be modified.

When Continuous Integration Meets Continuous Profiling

Continuous integration (CI) has been widely adopted across the globe. However, while any regression test can break the build, development teams are not accustomed to verifying database access performance as part of CI. Such ongoing performance monitoring can be used for breaking the build if a change is too costly, preventing unforeseen problems from sneaking into the code. Not only would it detect major problems that are accidentally checked in, but it would also detect minor ones that can pile up and make the database slower over time. To support continuous profiling, the NHibernate Profiler has a command-line interface and can output XML, HTML or JSON.

/CmdLineMode[+|-]         (short form /C)
/File:<string>            (short form /F)
/ReportFormat:{Xml|Html}  (short form /R)
/Port:<int>               (short form /P)
/InputFile:<string>       (short form /I)
/Shutdown[+|-]            (short form /S)

Furthermore, by using the API provided by the NHibernate Profiler, developers can get programmatic access to the profiler’s report. This is useful both for CI and as part of unit testing to assert on database-related functionalities.

Screenshot

Programmatic access allows creating build rules for CI and unit testing.

Conclusion

Using a dedicated profiler as part of the development process is important to ensure adequate database access performance and visibility. The NHibernate Profiler in particular, provides valuable insights into complex applications in a user-friendly GUI, supporting Azure, CI, and a wealth of alerts. The latest NHibernate Profiler version 6.0 brings a new GUI and improved performance, as well as newly added support for .NET core, Async/Await, and Azure. Version 6.0 is available for a 30 days free trial and is bundled with a free Cosmos DB Profiler when purchased.

To learn more about improving the visibility and performance of database interactions, please visit the NHibernate Profiler web page here.