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).
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]
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 ...'
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
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:
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 conclusionorg.hibernate.engine.internal.StatisticalLoggingSessionEventListener
as an inspirationNow 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
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:
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
:
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.
© 2007-2023 Florian Beaufumé