SQL logging and performance

Every performance problem in Hibernate shows up in the SQL it sends. So far hibernate.show_sql printed the statements, but it has drawbacks: it writes straight to the console, past the logging system, so its output cannot be filtered or sent to a file, and it does not show parameter values. In a real project SQL goes through the logging system, and Hibernate statistics count the queries for you.

Logging through Logback

Hibernate writes its messages through the JBoss Logging library, which picks up Logback when it is present. Add the dependency:

<!-- pom.xml -->
<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.5.38</version>
</dependency>

Create src/main/resources/logback.xml:

<!-- src/main/resources/logback.xml -->
<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%-5level %logger{20} - %msg%n</pattern>
    </encoder>
  </appender>
 
  <logger name="org.hibernate.SQL" level="DEBUG"/>
  <logger name="org.hibernate.orm.jdbc.bind" level="TRACE"/>
 
  <root level="WARN">
    <appender-ref ref="CONSOLE"/>
  </root>
</configuration>

Remove hibernate.show_sql from persistence.xml. Saving an author and a post now prints:

DEBUG org.hibernate.SQL - insert into Author (name,id) values (?,?)
TRACE o.h.orm.jdbc.bind - binding parameter (1:VARCHAR) <- [Anna]
TRACE o.h.orm.jdbc.bind - binding parameter (2:BIGINT) <- [1]
DEBUG org.hibernate.SQL - insert into Post (author_id,title,views,id) values (?,?,?,?)
TRACE o.h.orm.jdbc.bind - binding parameter (1:BIGINT) <- [1]
TRACE o.h.orm.jdbc.bind - binding parameter (2:VARCHAR) <- [Post 1]
TRACE o.h.orm.jdbc.bind - binding parameter (3:INTEGER) <- [0]
TRACE o.h.orm.jdbc.bind - binding parameter (4:BIGINT) <- [1]

Logger	Level	Shows
`org.hibernate.SQL`	`DEBUG`	Every SQL statement
`org.hibernate.orm.jdbc.bind`	`TRACE`	Parameter values

Parameter values may contain personal data, so the bind logger is for development only. Spring Boot uses Logback too; there the same loggers are set with logging.level.org.hibernate.SQL=debug.

Counting statements

Turn on statistics in persistence.xml:

<!-- src/main/resources/META-INF/persistence.xml -->
<property name="hibernate.generate_statistics" value="true"/>

and read them from the factory:

// src/main/java/com/example/blog/Stats.java
Statistics stats = emf.unwrap(SessionFactory.class).getStatistics();
stats.clear();
 
emf.runInTransaction(em -> em.createQuery("select p from Post p", Post.class)
        .getResultList()
        .forEach(p -> p.getAuthor().getName()));
IO.println("Without join fetch, statements: " + stats.getPrepareStatementCount());
 
stats.clear();
emf.runInTransaction(em -> em.createQuery("select p from Post p join fetch p.author", Post.class)
        .getResultList()
        .forEach(p -> p.getAuthor().getName()));
IO.println("With join fetch, statements: " + stats.getPrepareStatementCount());

Without join fetch, statements: 4
With join fetch, statements: 1

On the Seed data this is the N+1 problem as a number. Such a check fits well into a test.

JDBC batching

Hibernate can send many insert statements in one round trip. Add <property name="hibernate.jdbc.batch_size" value="20"/> and save 100 posts:

Inserted: 100, statements: 4

Without the property the same code needs 103 statements. Batching does not work with GenerationType.IDENTITY, because there each insert must run at once to get its id.

Habits that keep Hibernate fast

make @ManyToOne and @OneToOne lazy and load related data with join fetch or entity graphs;
set hibernate.default_batch_fetch_size as a safety net against N+1;
for lists and reports select only the needed fields into a record instead of whole entities;
paginate everything that can grow;
use a real connection pool (HikariCP) instead of the built-in one.

Common mistake

If you turn on the org.hibernate.SQL logger but forget to remove hibernate.show_sql, every statement is printed twice:

DEBUG org.hibernate.SQL - select p1_0.id,p1_0.author_id,p1_0.title,p1_0.views from Post p1_0 where p1_0.views>=?
Hibernate: select p1_0.id,p1_0.author_id,p1_0.title,p1_0.views from Post p1_0 where p1_0.views>=?

Use one of the two, and in production — the logger, at a level that can be changed without rebuilding.

Thanks for reading!