Follow @vlad_mihalcea Imagine having a tool that can automatically detect if you are using JPA and Hibernate properly. Hypersistence Optimizer is that tool!

Introduction

In this article, I’m going to show you how you can activate the slow query log when using JPA and Hibernate.

This slow query log feature has been available since Hibernate ORM 5.4.5 and notifies you when the execution time of a given JPQL, Criteria API or native SQL query exceeds a certain threshold value you have previously configured.

See how you can activate the slow query log when using JPA and Hibernate.https://t.co/bbqFzRHEEU — Java (@java) February 29, 2020

Domain Model

Let’s consider we have the following Post entity class in our application:

The Post entity is mapped as follows:

@Entity(name = "Post") @Table(name = "post") public class Post { @Id private Long id; private String title; @Column(name = "created_on") @CreationTimestamp private Date createdOn; @Column(name = "created_by") private String createdBy; //Getters and setters omitted for brevity }

We are going to persist 5000 Post entities so that we have enough data to generate queries that take more than 25 milliseconds:

LongStream .rangeClosed(1, 5000) .forEach(i -> { entityManager.persist( new Post() .setId(i) .setTitle( String.format( "High-Performance Java Persistence book - page %d review", i ) ) .setCreatedBy("Vlad Mihalcea") ); if(i % 50 == 0 && i > 0) { entityManager.flush(); } });

Hibernate slow query log

In order to activate the slow query log, you need to set the hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS property to a value that’s greater than 0 , representing the query execution threshold.

In our case, any query that takes more than 25 milliseconds will trigger the slow query log entry.

If you’re using Spring Boot, you can set this Hibernate setting in the application.properties configuration file:

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

If you’re using Java EE, you can set it via the persistence.xml configuration file:

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

And, Hibernate will log all SQL queries that took more than 25 milliseconds to be executed. In order to see the slow query log entry, you need to make sure you have the following logger name set to at least the info level:

<logger name="org.hibernate.SQL_SLOW" level="info"/>

To see how the Hibernate slow query log works, we can check the Hibernate org.hibernate.engine.jdbc.internal.ResultSetReturnImpl class which is used for all SQL query executions:

@Override public ResultSet extract( Statement statement, String sql) { sqlStatementLogger.logStatement(sql); long executeStartNanos = 0; if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) { executeStartNanos = System.nanoTime(); } try { final ResultSet rs; try { jdbcExecuteStatementStart(); rs = statement.executeQuery(sql); } finally { jdbcExecuteStatementEnd(); sqlStatementLogger.logSlowQuery( sql, executeStartNanos ); } postExtract(rs, statement); return rs; } catch (SQLException e) { throw sqlExceptionHelper.convert( e, "could not extract ResultSet" ); } }

So, the slow query log validates the underlying SQL query execution without taking into account how the ResultSet is transformed into entities, DTOs, Tuple instances, or the default Object[] array.

Testing time

Next, we are going to check how the SQl query logs work for both entity queries and native SQL statements.

JPQL queries

When executing the following JPQL query:

List<Post> posts = entityManager .createQuery(""" select p from Post p where lower(title) like :titlePattern order by p.createdOn desc """, Post.class) .setParameter( "titlePattern", "%Java%book%review%".toLowerCase() ) .setFirstResult(1000) .setMaxResults(100) .getResultList();

Hibernate generates the following slow query log entry:

o.h.SQL_SLOW - SlowQuery: 32 milliseconds. SQL: 'PgPreparedStatement [ select p.id as id1_0_, p.created_by as created_2_0_, p.created_on as created_3_0_, p.title as title4_0_ from post p where lower(p.title) like '%java%book%review%' order by p.created_on desc limit 100 offset 1000 ]'

So, it works!

The slow query threshold was set to 25 milliseconds, and, since the above SQL query took more than that, Hibernate added a slow query log entry.

Notice that the log entry was formatted on multiple lines to increase readability for this article. However, by default, there will be a single line of text containing the slow query log entry.

Criteria API queries

When executing this Criteria API query:

CriteriaBuilder builder = entityManager .getCriteriaBuilder(); CriteriaQuery<Post> postQuery = builder .createQuery(Post.class); Root<Post> post = postQuery.from(Post.class); postQuery .where( builder.like( builder.lower(post.get("title")), "%Java%book%review%".toLowerCase() ) ) .orderBy( builder.desc(post.get("createdOn")) ); List<Post> posts = entityManager.createQuery( postQuery ) .setFirstResult(1000) .setMaxResults(100) .getResultList();

Hibernate generates a slow query log entry, like this one:

o.h.SQL_SLOW - SlowQuery: 27 milliseconds. SQL: 'PgPreparedStatement [ select p.id as id1_0_, p.created_by as created_2_0_, p.created_on as created_3_0_, p.title as title4_0_ from post p where lower(p.title) like '%java%book%review%' order by p.created_on desc limit 100 offset 1000 ]'

Writing Criteria API queries is not very straightforward. That’s why it’s a good idea to use the Codota IDE plugin to help you with this task. Check out this article for more details about this topic.

Native SQL queries

When executing the native SQL query equivalent to the previous JPQL and Criteria API queries:

List<Post> posts = entityManager .createNativeQuery(""" SELECT p.* FROM post p WHERE LOWER(p.title) LIKE :titlePattern ORDER BY p.created_on DESC """, Post.class) .setParameter( "titlePattern", "%Java%book%review%".toLowerCase() ) .setFirstResult(1000) .setMaxResults(100) .getResultList();

We get a slow query log message written by Hibernate:

o.h.SQL_SLOW - SlowQuery: 27 milliseconds. SQL: 'PgPreparedStatement [ SELECT p.* FROM post p WHERE LOWER(p.title) LIKE '%java%book%review%' ORDER BY p.created_on DESC LIMIT 100 OFFSET 1000 ]'

In our case, the application query type doesn’t influence the slow query log since both JPQL and Criteria API generate SQL queries that are similar to the native SQL one we used in the last test case.

Conclusion

The Hibernate 5.4 slow query log is a very nice feature since it allows you to correlate slow queries with the application-specific business methods that were executing at that particular time.

Hypersistence Optimizer is also going to add support for slow queries, and it will consider the entity query parsing as well as the ResultSet transformation, so stay tuned for an awesome alternative that’s going to be available to all Hibernate versions since 3.3.

Insert details about how the information is going to be processed DOWNLOAD NOW