Hibernate slow query log

Imagine having a tool that can automatically detect JPA and Hibernate performance issues. 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.

Online Workshops

If you enjoyed this article, I bet you are going to love my upcoming 4-day x 4 hours High-Performance Java Persistence Online Workshop

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

15 Comments on “Hibernate slow query log

  1. As per the source code of SqlStatementLogger.logSlowQuery(String sql, long startTimeNanos){} in hibernate 5.4.20, the LOG_SLOW logger just outputs (on INFO level) the below String, I don’t know if there are further customization options, maybe in future versions.

    String logData = “SlowQuery: ” + queryExecutionMillis + ” milliseconds. SQL: ‘” + sql + “‘”;
    LOG_SLOW.info( logData );

    For our needs, I wrote a bash script using cut and sed to transform the slow sql logs ouput to a csv with only the needed data.

  2. That’s making the slow sql logs really easy to configure now, however I am not able to display the query params used in query for Oracle db. What is funny they are properly displayed for h2 in memory database used in tests (once I set logger to TRACE level).
    Is there any issue with that part of the logging or I need to additionally setup something at my end to have all query params visible in slow log for Oracle db?

    Ken

    • The problem you are facing is caused by HHH-13741 and/or HHH-13888. I created this PR some time ago, but it was never merged, and I’m no longer working for Red Hat, so I don’t know when that will happen.

  3. Thank you for this helpful article again, Vlad. Logs are perfectly formatted for Postgres. Do you have any insights so far if there’d be downsides when activating this in a production environment?

    • You could set a log appender that writes those queries asynchronously to a file. This will help speed up the current transaction because the SQL log will be written asynchronously. However, if the application crashed, then you might lose some logs, depending on how many were buffered but didn’t get a chance to be written.

      • I don’t see how transaction routing could affect logging. Try to debug and see why logs get lost. Maybe there are different log config files used by different microservices?

      • Finally figured this one out, for the routing data source, the LocalContainerEntityManagerFactoryBean is constructed manually, and not taking into account the “hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS” from the spring boot app’s application.properties file…

      • Thanks for investigating it. You could probably create the beans manually and i=override the Spring Boot ones to have more control, right?

  4. Is there a way to print logs on application side prior to version Hibernate v5.4. I am using 5.3.7.

  5. Thank your for this information.

    I’ve tried as you suggested, but instead of SQL statements, all I’ve got is the following printed:

    INFO: SlowQuery: 673761 milliseconds. SQL: ‘weblogic.jdbc.wrapper.PreparedStatement_oracle_jdbc_driver_OraclePreparedStatementWrapper@1b1b051’

    Any clue ?

    Regards,
    John

    • Hi,

      It seems in my case I’m at the mercy of Oracle driver to print SQL statements which it doesn’t.

      Regards

      • Hopefully, that Hibernate issue will get fixed.

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.