|

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.


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.

9 Comments

  1. Hi, Thorben!

    Is this parameter taken on-the-fly or server should be restarted?
    hibernate.generate_statistics=true

    Log contains no hibernate info, although log4j.logger.org.hibernate.stat=DEBUG

    Thank you.

    1. Avatar photo Thorben Janssen says:

      Hi Yana,

      that depends on the server you use, but in general, you need to restart it.

      Regards,
      Thorben

  2. Avatar photo Nam Nguyen Hoang says:

    Thank you Thorben

    It would be nice that the statistic log and the query statement log are printed out in another file.
    By adding a handler:

    I can log the query statement and time consumption into another file, but the statistic log is still in server.log file.

    Do you have any idea?

    Thank you
    Nam Nguyen

    1. Avatar photo Thorben Janssen says:

      Hi,

      that depends on the logging framework and server that you use.
      You can configure it in the same way as any other log message written by other frameworks.

      Regards,
      Thorben

  3. Thank you Thorben

    Mean time when considering LAZY load objects in Hibernate may lead to performance issue ? Due to it will execute SQL queries when accessing LAZY attributes. Does it has a solution ?

    Thank you
    Amila

  4. When persisting one record, Does Hibernate alwayes execute two queries? One for featching the current id(SELECT statement) and second one for persisting the data(INSERT statement).

    Thank you

  5. Hi Richard,

    thanks 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.

  6. I wish I knew this feature when I was developing my Hibernate's based application a year ago !

Comments are closed.