A Guide to Logging SQL Queries in Hibernate

show-sql=true

show-sql is the basic option in Hibernate to display the generated SQL Statements. It does print the statements to the console, so it is only a viable option if you analyze the output generated by Hibernate on a developer machine in an IDE or Terminal. It is not suited for production and big amounts of logs.

Since Hibernate works with prepared SQL Statements you won't see the actual parameter values. Most of the time for performance analysis this is OK. When it comes down to performance it's more important to know how much queries are executed, how do they look like, what columns they select from what tables, what are the joins and the WHERE clause. If we fetch a BankAccount with an IBAN X or Y most of the times this does not matter.

logging.level.org.hibernate.SQL=DEBUG

The alternative to show-sql is logging SQL Statement using a logging framework. By setting logging.level.org.hibernate.SQL (in Spring Boot) to DEBUG we get the same output as with show-sql, but the output is written to the console as well as to the file and other logging destinations depending on our logging configuration.

So for the following JPQL Query:

import org.springframework.data.jpa.repository.JpaRepository;
import org.springframework.data.jpa.repository.Query;

public interface BankAccountRepository extends JpaRepository<BankAccount, Long>{

    @Query(value = "Select b From BankAccount b where b.iban = :iban")
    List<BankAccount> findAllBankAccountsByIban(String iban);

}

the output will be something like:

select ba1_0.id,ba1_0.bic,ba1_0.iban from bank_account ba1_0 where ba1_0.iban=?

format-sql=true

While show-sql will show you the SQL Query, it will do so in one line, which for bigger queries makes it hard to read. That's why you should enable format-sql to see nicely formatted SQL Queries. The same formatting will be applied to queries logged by the logging framework.

    select
        ba1_0.id,
        ba1_0.bic,
        ba1_0.iban
    from
        bank_account ba1_0
    where
        ba1_0.iban=?

highlight-sql=true

If you decide to look at your queries in a terminal which supports coloring this option will color the SQL keywords. Do not use this if you log to a file. If you do so you’ll see markers which are responsible for coloring the output in a terminal which support coloring.

    select
        ba1_0.id,
        ba1_0.bic,
        ba1_0.iban
    from
        bank_account ba1_0
    where
        ba1_0.iban=?

use_sql_comments=true

If you find some SQL Queries which you'd like to optimize you need to know what generated them. Usually it originates from a JPQL Query or Criteria Query or something like that. Sometimes it easy to find the (source) JPQL Query based on the first table in the FROM clause and the WHERE clause. Sometimes it's harder. In order to find it quickly without guessing use_sql_comments logs the JPQL Query which generated the SQL Statements and you'll easily know which query to optimize.

    /* Select
        b
    From
        BankAccount b
    where
        b.iban = :iban */ select
            ba1_0.id,
            ba1_0.bic,
            ba1_0.iban
        from
            bank_account ba1_0
        where
            ba1_0.iban=?

@Meta

Spring Data JPA allows you to put custom comments on JPQL Queries. This is done using the @Meta annotation.

import org.springframework.data.jpa.repository.JpaRepository;
import org.springframework.data.jpa.repository.Meta;
import org.springframework.data.jpa.repository.Query;

public interface BankAccountRepository extends JpaRepository<BankAccount, Long>{

    @Meta(comment = "Important Query to keep an eye on")
    @Query(value = "Select b From BankAccount b where b.iban = :iban")
    List<BankAccount> findAllBankAccountsByIban(String iban);

}

The above Query, with the @Meta annotation will log the following statement:

    /* Important Query to keep an eye
        on */ select
            ba1_0.id,
            ba1_0.bic,
            ba1_0.iban
    from
        bank_account ba1_0
    where
        ba1_0.iban=?

generate_statistics=true

A useful thing to enable when analyzing the performance of Hibernate queries is generate_statistics. It shows you a few time based stats like how long it too to prepare and execute the query. It also shows you how many SQL Queries were generated for a given JPQL Query. It's important to know that one JPQL Query can result in many SQL Queries for example if you stumble on the N+1 problem. Hence a JPQL query not neccesarily translates into one SQL Query. If you find a case where you have multiple SQL queries for one JPQL Query it's often a sign that it can (or should) be optimized.

My personal pain-point with this is that the times are printed in nanoseconds. Mili- or microseconds would be easier to read by humans.

2024-09-23T22:45:46.250+02:00 DEBUG 14068 --- [jpa-tests] [  restartedMain] org.hibernate.SQL                        : 
    /* Select
        b
    From
        BankAccount b
    where
        b.iban = :iban */ select
            ba1_0.id,
            ba1_0.bic,
            ba1_0.iban
        from
            bank_account ba1_0
        where
            ba1_0.iban=?
2024-09-23T22:45:46.268+02:00  INFO 14068 --- [jpa-tests] [  restartedMain] i.StatisticalLoggingSessionEventListener : Session Metrics {
    1022900 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    9869200 nanoseconds spent preparing 1 JDBC statements;
    2443100 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    0 nanoseconds spent executing 0 pre-partial-flushes;
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

Hibernate Slow Query Log

All previous points should not be used it production because it can easily flood your logs. They are intended for local development where you investigate a performance problem and can narrow it down to a action in your system or a test case. What you can enable in production however is Hibernates Slow Query Log. It allows you to specify a threshold in milliseconds and when an SQL Query takes longer to execute then this threshold it will be logged and you have a candidate for optimization.

The Spring Boot configuration for the Slow query log needs the threshold set and the log level to info:

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

logging.level.org.hibernate.SQL_SLOW=info

By default only the prepared statement will be logged.

2024-09-23T23:00:48.398+02:00  INFO 17048 --- [jpa-coaching] [  restartedMain] org.hibernate.SQL_SLOW                   : Slow query took 4 milliseconds [select ba1_0.id,ba1_0.bic,ba1_0.iban from bank_account ba1_0 where ba1_0.iban=?]

If you have use_sql_comments enabled also the JPQL Query will be logged:

2024-09-23T22:56:16.351+02:00  INFO 14068 --- [jpa-coaching] [  restartedMain] org.hibernate.SQL_SLOW                   : Slow query took 2 milliseconds [/* Select b From BankAccount b where b.iban = :iban */ select ba1_0.id,ba1_0.bic,ba1_0.iban from bank_account ba1_0 where ba1_0.iban=?]

VisualVM JDBC Monitoring

If you want to get an birds-eye-view of what is going in your application and query logging like above logs too much a good option to use i VisualVM. VisualVM on itself it s profiler - a tool to analyze performance of JVM applications. However a special feature of VisualVM is JDBC Monitoring. It captures all SQL which went through JDBC, so not only SQL statements generated by Hibernate. It will show all the queries with their number of executions. Then you can sort it by this execution count and so you can look if some queries are executed more times then you'd expect it.

Summary

Logging the SQL queries generated by Hibernate is the best way to analyze performance problems. With the settings mentioned above, you'll get a clear overview of what needs to be optimized to improve the database performance of your app.