Hibernate Slow Query Log – The easiest way to find slow queries

---

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!

---

One of the common questions when analyzing a slow application is if there are any slow database queries. You can, of course, monitor these queries on your database. But then you still need to match them with a part of your Java code. And because there is no easy way to see what happened immediately before or after a specific query, this can take much more effort than it should. Since Hibernate 5.4.5, you can also get this information from Hibernate’s slow query log. Its integration into your application log can make your analysis a lot easier.

As I explain in my logging guide, you should use 2 different logging configurations. One for production that keeps the overhead as low as possible. And one for development that provides you as much information about your application as possible. Hibernate’s slow query log should be part of the development configuration, and you should adjust its settings based on the size of your test database. The smaller that database, the lower the threshold of your slow query log should be.

Activating Hibernate’s Slow Query Log

You can activate the slow query log in your configuration in 2 steps:

1. You need to configure the threshold above which Hibernate considers a query as slow.
2. Hibernate’s logging configuration needs to include the slow query messages.

Configuring Slow Query Threshold

The decision if a query is slow depends on lots of different factors, like the performance requirements of your application, the size of your database, your deployment scenario, and the available resources. You need to define this threshold for your specific application and test scenario.

Using Hibernate’s slow query log, you can define this threshold using the hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS property.

If you’re using plain Hibernate, you can set this property in your persistence.xml configuration.

<persistence>
	<persistence-unit name="my-persistence-unit">
		...

		<properties>
            <property name="hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS" value="20" />

			...
		</properties>
	</persistence-unit>
</persistence>

For a Spring Boot application, you can set it in your application.properties file by adding the prefix spring.jpa.properties to the property’s name.

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=20

Attention: Hibernate applies this threshold to the pure execution time of the query. This doesn’t include any of Hibernate’s preparation or result processing steps and is lower than the time reported in Hibernate’s statistics!

Activating Logging

After you defined the threshold for slow queries, Hibernate will write a log message for each query that takes longer than the specified threshold. It writes this message in the INFO level to the category org.hibernate.SQL_SLOW. So, please make sure to configure your logging accordingly.

org.hibernate.SQL_SLOW=info

Examples

Hibernate supports the slow query log for all types of queries. This includes JPQL statements, the Criteria API, native queries, and the queries triggered by methods of the EntityManager.

In the following code snippet, I use the previously discussed configuration and execute a native SQL query that selects all Author entities from the database.

EntityManager em = emf.createEntityManager();
em.getTransaction().begin();

Query q = em.createNativeQuery("SELECT * FROM Author a", Author.class);
q.getSingleResult();

em.getTransaction().commit();
em.close();

If the database takes longer than the configured threshold, Hibernate writes the following message to the log file.

18:06:52,204 INFO  [org.hibernate.SQL_SLOW] - SlowQuery: 26 milliseconds. SQL: 'SELECT * FROM Author a'
18:06:52,221 DEBUG [org.hibernate.stat.internal.StatisticsImpl] - HHH000117: HQL: SELECT * FROM Author a, time: 47ms, rows: 100

The first line is part of the slow query log. As you can see, the database took 26 milliseconds to execute this query. In the second line, you can see a message from Hibernate’s statistics component. Hibernate there reports an execution time of 47ms, which is almost twice as long. That’s because the slow query log only considers the query’s pure execution time, while the time measured by Hibernate’s statistics also includes the result processing.

Conclusion

As you have seen, you can easily activate Hibernate’s slow query log in your configuration. Hibernate then measures how long it took the database to process each query. For each query that was slower than the configured threshold, Hibernate writes a message to the log file.

This log configuration is very helpful to identify slow database queries within your application. But please keep in mind that the slow query log only measures the database’s pure execution time. The time Hibernate takes to process the result is not included but can have a huge impact on the overall performance of your query.