Hibernate slow query log

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.

Domain Model

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

Post entity used for the SQL Query Log

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 workshopk on the 14th of May about The Best Way to Fetch Data with Java Persistence and Hibernate.

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.

Transactions and Concurrency Control eBook

4 Comments on “Hibernate slow query log

  1. Wow it is a cool feature. Would it be possible to subclass SqlStatementLogger and to use own one?
    Long story short, I’m Oracle DBA and I’m facing similar issues every day. But it would be much easier if I was able to relate slow running query with application action, so I mine custom logger would also log some app relevant request id.

    Also in case of Oracle I do not need full nor partial SQL text. All I need is a SQL_ID which is last 5 bytes of SQL’s MD5 checksum. If I had SQL_ID I could find “everything” about SQL query performance in Oracle’s active session history.

    Moreover many of SQL performance problems are caused by data skews, so even if a slow SQL is logged it is worthless without knowing particular bind variables. Those I can deduce either by getting app’s data from thread context or by digging inside JDBC drivers internals.

  2. Very good article and feature, Vlad. I didn’t know that, thanks for sharing it!

    One question: you said the slow query log entry is not formatted by default. So, is there any way to configure it to be formatted? Or does it apply the Hibernate format_log setting?

    • That’s a good question. Frankly, I don’t know. I’ll have to check the source code to find the answer.

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.