Table of contents

• Introduction
• SQL logging
• Slow queries logging
• Statement metrics
• Session metrics
• Session factory metrics
• Database connection pool metrics
• Conclusion

Introduction

Hibernate is a powerful ORM. It comes with several monitoring features such as logs and metrics/statistics. They can provide valuable insights of the behavior of the persistence layer, in order to optimize the application performances or troubleshoot mapping issues.

These features can be used by applications that directly use Hibernate. They also run fine with high level application frameworks such Spring Boot (for example using Spring Data JPA), Java/Jakarta EE or others.

Several of these features are activated using Hibernate configuration parameters. They can be defined in various places such as hibernate.cfg.xml from Hibernate or persistence.xml from Java/Jakarta EE. If you use Spring Boot, you can directly set the Hibernate configuration parameters in your Spring Boot configuration using the spring.jpa.properties prefix. For example the hibernate.format_sql Hibernate parameter is spring.jpa.properties.hibernate.format_sql in the Spring Boot configuration.

Note that this article was written along with a demo application (see link in the conclusion) using Hibernate 5.6.11 (from Spring Boot 2.7.4) and 6.1.5 (from Spring Boot 3.0.1).

SQL logging

Probably the most known and used monitoring feature. Hibernate can log all the executed SQL statements. Usually not recommended in production, it is very useful during development to review the generated SQL and identify persistence issues (N+1 select problems, unintended lazy loadings, etc).

It can be enabled by setting the hibernate.show_sql Hibernate parameter to true. With Spring Boot set spring.jpa.properties.hibernate.show_sql to true as described in the introduction, or simply set spring.jpa.show-sql to true. A sample output:

Hibernate: select author0_.id as id1_0_, author0_.name as name2_0_ from author author0_

If you prefer multi-line SQL logs, additionally set hibernate.format_sql Hibernate parameter to true:

Hibernate:
    select
        author0_.id as id1_0_,
        author0_.name as name2_0_
    from
        author author0_

Hibernate can also prefix the SQL statement by some comment (by default this is the HQL query, but it can be customized programmatically) by setting hibernate.use_sql_comments to true. It support both single-line and multi-line SQL logs. A sample output:

Hibernate:
    /* select
        generatedAlias0
    from
        Author as generatedAlias0
    where
        generatedAlias0.name=:param0 */ select
            author0_.id as id1_0_,
            author0_.name as name2_0_
        from
            author author0_
        where
            author0_.name=?

The previous logs do not integrate with the logging framework, meaning that no timestamp or thread name is logged. If you prefer the SQL logs to integrate with the logging framework, the configuration is a bit different. It does not use a configuration parameter, but simply set the org.hibernate.SQL category to DEBUG in the logging configuration. When using Spring Boot it can be done by setting logging.level.org.hibernate.SQL to debug. A truncated sample output:

19:19:26.720 DEBUG [nio-8080-exec-1] org.hibernate.SQL                        : select ...

These integrated logs also support hibernate.format_sql and hibernate.use_sql_comments parameters.

To log the parameters of the SQL statements, set the org.hibernate.type.descriptor.sql.BasicBinder log category to TRACE (for Hibernate 5) or the org.hibernate.orm.jdbc.bind category to TRACE (for Hibernate 6). A truncated sample output:

19:34:55.163 DEBUG [nio-8080-exec-2] org.hibernate.SQL                        : select ... where author0_.name=?
19:34:55.163 TRACE [nio-8080-exec-2] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [Tolkien]

Slow queries logging

Hibernate 5.4.5 and higher can selectively log the SQL statements that last more than a certain duration. This is useful to identify the slow queries of the application.

It can be enabled by setting the hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS Hibernate parameter to the target duration in milliseconds, for example 100. A truncated sample output:

19:37:21.128  INFO [nio-8080-exec-2] org.hibernate.SQL_SLOW                   : SlowQuery: 137 milliseconds. SQL: 'HikariProxyPreparedStatement@1736163819 wrapping select ...'

Statement metrics

Hibernate can provide metrics about the executed statements. First enable the statistics by setting the hibernate.generate_statistics Hibernate parameter to true then set the org.hibernate.stat log category to DEBUG to get the execution duration and the number of rows for the executed statements at the end of the log:

17:32:31.415 DEBUG [nio-8080-exec-3] o.h.stat.internal.StatisticsImpl         : HHH000117: HQL: select generatedAlias0 from Author as generatedAlias0 where generatedAlias0.name=:param0, time: 4ms, rows: 1

Session metrics

Hibernate can provide session metrics, also known as L1 stats. First enable the statistics as seen before then set the org.hibernate.engine.internal.StatisticalLoggingSessionEventListener log category to INFO. As a consequence whenever an Hibernate session ends, a summary of the database operations executed during that session is logged:

17:44:21.361  INFO [nio-8080-exec-8] i.StatisticalLoggingSessionEventListener : Session Metrics {
    26000 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    119900 nanoseconds spent preparing 13 JDBC statements;
    1006100 nanoseconds spent executing 13 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;
    959100 nanoseconds spent executing 1 flushes (flushing a total of 10 entities and 4 collections);
    3300 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

These logs contain useful information but may arguably be hard to read. Instead it is possible to provide our own custom implementation:

• The Hibernate statistics are not needed, you may disable them
• Set the hibernate.session.events.auto Hibernate property to the FQCN (fully qualified class name) of our implementation, for example com.adeliosys.sample.CustomSessionEventListener in the sample project linked in the article conclusion
• Code that class using org.hibernate.engine.internal.StatisticalLoggingSessionEventListener as an inspiration
• Make sure the log level used in the custom implementation is enabled

Now the log may look like:

12:33:07.814 DEBUG [nio-8080-exec-5] c.a.sample.CustomSessionEventListener    : Session metrics:
    connections  : acquired 1 (46 μs)
    statements   : prepared 13 (112 μs), executed 13 (1117 μs)
    JDBC batches : executed 0 (0 μs)
    cache        : 0 puts (0 μs), 0 hits (0 μs), 0 misses (0 μs)
    flushes      : executed 1 (1020 μs) for 10 entities and 4 collections, executed 1 partials (5 μs) for 0 entities and 0 collections

Session factory metrics

Hibernate can provide session factory metrics, also known as L2 stats. They are useful to understand the persistence operations that are executed over time, the most used entities, the most frequent or slow queries, etc. Session factory metrics can also be enabled by setting hibernate.generate_statistics to true or programmatically by executing sessionFactory.getStatistics().setStatisticsEnabled(true). Then you can use the statistics API to get many information:

// To get the SessionFactory from the EntityManagerFactory, if needed
SessionFactory sessionFactory = entityManagerFactory.unwrap(SessionFactory.class);

Statistics stats = sessionFactory.getStatistics();

// The number of sessions opened by this session factory so far
long openedSessionCount = stats.getSessionOpenCount();

// The number of inserts for the book entity
EntityStatistics bookEntityStats = stats.getEntityStatistics(Book.class.getName());
long bookInsertCount = bookEntityStats.getInsertCount();

// The average duration of a query
String[] queries = stats.getQueries();
QueryStatistics queryStats = stats.getQueryStatistics(queries[0]);
long averageDuration stats.getExecutionAvgTime();

I often generate a simple HTML page that summarizes the statistics. Here is a snapshot from the sample project linked in the article conclusion:

Hibernate can also expose the session factory metrics through JMX. Note that this is not supported by Hibernate 6. To enable this feature, additionally set hibernate.jmx.enabled to true, then connect with your preferred JMX client. A sample snapshot using JConsole:

Database connection pool metrics

Most database connection pool libraries provide usage metrics. This is actually not an Hibernate feature but it is closely related and can be very useful to tune the connection pool and prevent bottlenecks. Hikari, the connection pool used by Spring Boot by default, has an API to get metrics, for example:

// To get the Hikari data source from the data source
HikariDataSource hikariDataSource = (HikariDataSource) dataSource;

// The maximum number of connections, defined by the "maximumPoolSize" config param,
// see all config params in https://github.com/brettwooldridge/HikariCP
int totalConnections = hikariDataSource.getHikariPoolMXBean().getTotalConnections();

// The currently active (i.e. used) number of connections
int activeConnections = hikariDataSource.getHikariPoolMXBean().getActiveConnections();

// The number of threads currently waiting for an available connection
int threadsWaiting = hikariDataSource.getHikariPoolMXBean().getThreadsAwaitingConnection();

Hikari by default exposes an MBean providing the configuration parameters (maximum pool size, idle timeout, etc). To additionally expose the usage metrics (active connections, threads waiting, etc), make sure to set the registerMbeans Hikari configuration parameter to true. When using Spring Boot this can be done by setting spring.datasource.hikari.register-mbeans to true. Then from your JMX client, the MBeans can be found under com.zaxxer.hikari:

Conclusion

We saw how to use several Hibernate monitoring features such as logs and metrics/statistics. They helped me troubleshoot and optimize the persistence layer of many applications. I hope they will help you too.

A sample project is available in GitHub, see hibernate-monitoring. The project README describes how to use the application.