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.

I'm running an online workshop on the 20-21 and 23-24 of November about High-Performance Java Persistence.

If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.

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