How to activate Hibernate Statistics to analyze performance issues

---

Take your skills to the next level!

The Persistence Hub is the place to be for every Java developer. It gives you access to all my premium video courses, monthly Java Persistence News, monthly coding problems, and regular expert sessions.

Join the Persistence Hub!

---

Did you ever ask yourself why a server request took ages on the production system while your local test system was just fine?
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 let’s 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.

@Entity
public class Product implements Serializable
{
   @Id
   @GeneratedValue(strategy = GenerationType.AUTO)
   @Column(name = "id", updatable = false, nullable = false)
   private Long id = null;
   
   @Version
   @Column(name = "version")
   private int version = 0;
   
   @Column
   private String name;

   ...
}

We use this in a loop to store 10 records in the database and query them afterward.

for (int i=0; i<10; i++) {
   Product p = new Product();
   p.setName("MyProduct"+i);
   this.em.persist(p);
}

this.em.createQuery("Select p From Product p").getResultList();

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 of how much time was spent 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.

Log output

If we execute the test code to store 10 Product entities in the database and read them from the database afterward, Hibernate writes the following log messages:

20:28:52,484 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (default task-1) HHH000117: HQL: Select p From Product p, time: 0ms, rows: 10
20:28:52,484 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-1) Session Metrics {
    8728028 nanoseconds spent acquiring 12 JDBC connections;
    295527 nanoseconds spent releasing 12 JDBC connections;
    12014439 nanoseconds spent preparing 21 JDBC statements;
    5622686 nanoseconds spent executing 21 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    403863 nanoseconds spent executing 1 flushes (flushing a total of 10 entities and 0 collections);
    25529864 nanoseconds spent executing 1 partial-flushes (flushing a total of 10 entities and 10 collections)
}

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 of 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 this kind of issue 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 afterward, 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.