Well, we all had these situations and we will have several more of them in the future. In my experience, strange performance drops are often related to slow database queries. But which query causes the problem? And how to find it, if you can't or don't want to activate logging on your database?
The good news is, there is an easy way to do it. Hibernate can be configured to collect statistics and to provide the required information to analyze the database queries. So lets see what we need to do.
Demo application
Let's begin with a simple demo application. I know your production code is way more complex, but we only need a few database requests for our statistics. Therefore we will use a Product entity with an ID, a version and a name.We use this in a loop to store 10 records in the database and query them afterwards.
Configuration
The first thing we need to do is tell Hibernate to generate statistics for us. Therefore we need to set the system property hibernate.generate_statistics to true. Statistics are deactivated by default because it has a bad influence on the performance. So only activate them when you need them.
Now Hibernate will write one multi-line log statement with summarized statistical information at the end of the session. This is quite useful to get an overview on how much time was spend on database communication. But in most cases we need more information. We need to know, if there was a specific query that took a long time or if we have an overall performance issue. Therefore we would like to log the execution time for each query. This can be done by setting the log level for org.hibernate.stat to DEBUG.
I used a Wildfly 8.1.0.Final application server with Hibernate 4.3.5 for this example and did the described configuration changes by adding the following lines to the standalone.xml file.
Now Hibernate will write one multi-line log statement with summarized statistical information at the end of the session. This is quite useful to get an overview on how much time was spend on database communication. But in most cases we need more information. We need to know, if there was a specific query that took a long time or if we have an overall performance issue. Therefore we would like to log the execution time for each query. This can be done by setting the log level for org.hibernate.stat to DEBUG.
I used a Wildfly 8.1.0.Final application server with Hibernate 4.3.5 for this example and did the described configuration changes by adding the following lines to the standalone.xml file.
Log output
If we execute the test code to store 10 Product entities in the database and read them from the database afterwards, Hibernate writes the following log messages:
As you can see, the specific statistics for the select statement and the overall session statistics were written to the log file.
The statistics of the select statement show the number or returned rows (10) and the execution time of the statement (0ms). This would be the place where we would identify a slow statement. But there is obviously no performance issue with this simple query ;-)
The overall statistics provide information about the number of used JDBC connections and statements, the cache usage and the performed flushes. Here you should always check the number of statements first. Lots of performance issues are caused by n+1 select issues that can result in lots of additional queries. You can find more information about how to fix these kind of issues here: 5 ways to initialize lazy relations and when to use them.
If you wonder why Hibernate used 21 instead of 11 JDBC statements to store 10 Product entities and read all of them afterwards, you need to set org.hibernate.SQL to DEBUG to get more information. Hibernate required 2 statements to store each new product in the database because it selected the ID of each entity from a database sequence first and used it to store a fully initialized entity in the database.
Conclusion
If you need to analyze performance issues, Hibernate can collect and log useful statistics about each database query and the whole session. This needs to be activated by setting the system property hibernate.generate_statistics to true and the log level for org.hibernate.stat to DEBUG.You can then decide, if the performance issue is caused by the database communication or by some other part of the system. If it is caused by the database communication, you can see if you need to fix it in your Java code or if you need to contact your database administrator to get more detailed information about your slow queries.
You enjoyed this article and like to learn more about Java EE? Make sure to subscribe below or follow me on twitter and google+.
I wish I knew this feature when I was developing my Hibernate's based application a year ago !
ReplyDeleteHi Richard,
Deletethanks for your comment.
Yes, this is a really useful feature to get a better understanding about Hibernate and the performance issue. You often still need more information from your DBA but you know at least what you're looking for.