Hibernate is an amazing tool used by a majority of Java developers to hide the complexity of querying and modifying a relational database. However, the very complexity it hides can sometimes create issues that are hard to understand and fix. One of the biggest challenges that Hibernate users face is determining how much information and in which way will be queried from the database.
This can sometimes lead to production issues, when either too much data is pumped from the database, causing throughput issues, or too many SQL queries are issued, causing high latency. Forums and StackOverflow are full of requests to help debug such issues.
The typical way to solve them is getting Hibernate to dump the queries it is issuing to the database. This is fairly straightforward, but the queries are need to be connected back to the source and printing the parameters is additional trouble. The real way to solve those issues quickly and easily is using an interactive profiler, like XRebel, to get insight in how and what queries are issued to the database.
Let’s look at an example – just downloading the Spring Petclinic and enabling XRebel to run with it right away shows us an issue:
XRebel is an always-on, interactive profiler that runs in the background and notifies the user when and if an issue is detected. In this case, it has raised an alert that too many queries are issued to render this page. As you can imagine, 24 queries to render a simple page is overkill. To find out what is happening, let’s click on the toolbar and see the drilldown.
Looking at the drilldown we can see several things:
- 24 queries are issued from the method JpaOwnerRepositoryImpl.findByLastName
- The 24 total queries break down into one query to the Owners table, 13 queries to the Visits table and 10 queries to the Pets table (does not fit on the screenshot)
- The 12 Visits queries and the 10 Pets queries are the same except for the parameters highlighted in red. XRebel conveniently groups same queries under one group.
Looking at the JpaOwnerRepositoryImpl.findByLastName method we find that it issues a single Hibernate query:
SELECT owner FROM Owner owner WHERE owner.lastName LIKE :lastName
It looks that this simple query is then translated to 24 SQL queries. This is an amazingly common problem as testified e.g. by Tuomaala Petri, from Elbit Oy:
Our application have been developed by multiple folks over decades, so we found some very interesting side-effects right away. The worst of those was some badly coded Hibernate which would generate over 700 database queries on some pages. We also found some surprisingly slow SQL, which should not have been that slow.
Interactive profilers like XRebel are great at uncovering such issues before they go to production and cause slowdowns or outages. In the next article we will look into how to solve such issues when we find them by tweaking Hibernate FetchType and join modes.