Spring Boot and Hibernate, measure the performances

How to show Hibernate statistics using Spring Boot?

Hibernate is a great tool available for the Java developers, but can hide some of its logic behind some 'magic'.

The goal of this post is to show how to configure Spring Boot and Hibernate to show some statistics to help us to reduce the risk of bottleneck queries.

How to configure hibernate to show execution statistics

The first step is to ask hibernate to show some execution statistics.

Usually, we use

spring.jpa.show-sql=true 

to show the query executed, but we are trying to get more information from Hibernate for this reason we are adding the following lines in our Spring Boot application.properties:

logging.level.org.hibernate.stat=DEBUG 
spring.jpa.properties.hibernate.generate_statistics=true 

We are using JPA for this reason we use the spring.jpa.properties prefix. This configuration should not be used in production (besides exceptions) because it will slow down the execution of your queries and fill your log with information.

This is an example of log produced:

2024-01-01T11:46:47.613+02:00 DEBUG 87703 --- [nio-8080-exec-2] o.h.stat.internal.StatisticsImpl         : HHH000117: HQL: [CRITERIA] select w1_0.id,w1_0.comment,w1_0.ticker,w1_0.watchlist_id from watchlist_ticker w1_0, time: 24ms, rows: 169 
2024-01-01T11:46:47.616+02:00  INFO 87703 --- [nio-8080-exec-2] i.StatisticalLoggingSessionEventListener : Session Metrics { 
    1444000 nanoseconds spent acquiring 1 JDBC connections; 
    0 nanoseconds spent releasing 0 JDBC connections; 
    910459 nanoseconds spent preparing 1 JDBC statements; 
    8752124 nanoseconds spent executing 1 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; 
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections); 
    6875 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections) 
} 

The first line shows the query executed by Hibernate. At the end of the line you can see the execution time and the number of results: time: 24ms, rows: 169

The INFO shows a breakdown of the execution with some details.

Where are the details of the statistics collected by Hibernate?

In the official Hibernate documentation you can find more details: https://docs.jboss.org/hibernate/stable/orm/javadocs/org/hibernate/stat/Statistics.html

Can I enable or disable the statistics at runtime?

Particularly interesting if you need to run these performance statistics in Production you can enable or disable them programmatically using setEnableStatistics.

How to trace only queries that are slow?

If you want to show only the queries that are 'slow' you can ask Hibernate to log the queries that uses more that a specified threshold in milliseconds:

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=5 
logging.level.org.hibernate.SQL_SLOW=INFO 

This is an example of result showed by Hibernate:

2024-01-01T226T22:41:28.995+02:00  INFO 88842 --- [nio-8080-exec-3] org.hibernate.SQL_SLOW : SlowQuery: 10 milliseconds. SQL: 'HikariProxyPreparedStatement [HikariProxyPreparedStatement@1858344685 wrapping select d1_0.date,d1_0.ticker_ticker,d1_0.close,d1_0.high,d1_0.low,d1_0.open,d1_0.timestamp,d1_0.volume,d1_0.volume_weighted,s1_0.date,s1_0.ticker_ticker,s1_0.atr50,s1_0....'