Choosing the right logging configuration can make the difference between finding a performance issue during development or suffering from it on production. But it can also create an overhead that slows down your application. You need to decide which information you need and configure your system accordingly.
I, therefore, prefer to use two different configurations:
And in addition to the target system, your configuration also depends on the Hibernate version you’re using. That’s especially the case for your development configuration. Some logging features, like the slow query log, aren’t available in older Hibernate versions, and Hibernate 6 changed the names of a few important logging categories.
Because of that, I will explain the different log categories and provide you with my recommended logging configurations for development and production when using Hibernate 4, 5, and 6.
Before we look at the different logging categories and levels, let’s have a short look at the logging frameworks supported by Hibernate. Since version 4.0, Hibernate uses the JBoss Logging library to write messages to a log file. This library is a logging bridge that integrates different log frameworks. You can decide which of the following frameworks you want to use for your application:
You only need to add your preferred framework to the classpath, and the JBoss Logging library will pick it up. If multiple frameworks are available, it picks the one with the highest priority.
The concepts and log categories are the same for all frameworks, but the configuration file’s format and log level’s names can differ. I will show a few different configuration files in this article. Please check the documentation of your logging framework if yours is not included.
Like all applications and frameworks, Hibernate writes log messages in different categories and log levels.
The categories group log messages for specific topics, like executed SQL statements or cache interactions. The following table shows the most important log categories used by Hibernate:
Category | Description |
---|---|
org.hibernate | This category contains all messages written by Hibernate. You can use this to analyze unspecific issues or find categories used by Hibernate. Setting this category to a fine log level might create a lot of log output. |
org.hibernate.SQL | All SQL statements executed via JDBC are written to this category.You can use it together with org.hibernate.type.descriptor.sql or org.hibernate.orm.jdbc.bind to get more information about the JDBC parameters and results. |
org.hibernate.type.descriptor.sql | Hibernate 4 and 5 Hibernate writes the values bound to the JDBC parameters and extracted from the JDBC results to this category. This category should be used together with org.hibernate.SQL to also log the SQL statements. |
org.hibernate.orm.jdbc.bind | Hibernate 6 Hibernate writes the values bound to the JDBC parameters to this category. This category should be used together with org.hibernate.SQL to also log the SQL statements. |
org.hibernate.SQL_SLOW | Hibernate >= 5.4.5 Hibernate writes a message to the slow query log if the execution of an SQL statement took longer than the configured threshold (see Slow Query Log). |
org.hibernate.pretty | Hibernate logs the state at flush time of max. 20 entities to this category. |
org.hibernate.cache | Information about second-level cache activities is written to this category. |
org.hibernate.stat | Hibernate writes some statistics for each query to this category. The statistics need to be activated separately (see Activate Hibernate Statistics). |
org.hibernate.hql.internal.ast.AST | Hibernate 4 and 5 This category groups the HQL and SQL ASTs during query parsing. |
org.hibernate.tool.hbm2ddl | Hibernate writes the DDL SQL queries executed during schema migration to this log category. |
The names of the log levels are defined by your logging framework and define the amount and granularity of the log messages. You can assign a log level to each category. If you do not specify a log level for a specific category, it will inherit the level from its parent category.
How to get Hibernate to log the executed SQL queries is an often asked question, and the most popular answer on the internet seems to be to set the show_sql parameter in the persistence.xml to true. But please, don’t do this!
Hibernate provides two ways to activate the logging of the executed SQL queries, and setting the show_sql parameter to true is the worse one. It has two huge disadvantages:
The better way to activate the logging of executed SQL statements is to set the log level of the org.hibernate.SQL category to DEBUG (or the corresponding log level of your log framework). Hibernate will write the SQL statements without any information about the values bound to the JDBC parameters or extracted from the query result. If you also want to get this information, you have to set the log level of org.hibernate.type.descriptor.sql to DEBUG (see the development recommendation for an example).
The requirements for production and development systems are very different. During development, you need to know what Hibernate is doing in the background. But logging this information slows down the application, and it’s not required in production. I, therefore, recommend using two different settings:
Hibernate is doing many things for you in the background, which makes it easy to forget that you are still working with a database. But if you want to make sure that your application will perform as you expected, you need to check the number of executed queries and their SQL statements.
You need to set the log level for the org.hibernate.SQL category to DEBUG to get this information. If you also want to log the used bind parameter values, you also need to set the org.hibernate.type.descriptor.sql category (Hibernate 4 & 5) or the org.hibernate.orm.jdbc.bind category (Hibernate 6) to trace.
In addition to that, I prefer to activate Hibernate statistics to get a summary of the most critical metrics at the end of each session. And if you’re using Hibernate in at least version 5.4.5, I also recommend activating Hibernate’s slow query log.
You can see such a logging configuration for different logging frameworks in the following sections.
###
# Global configuration for all Hibernate versions
###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] - %m%n
log4j.rootLogger=info, stdout
###
# Hibernate < 5.4.5
###
# basic log level for all messages
log4j.logger.org.hibernate=info
# SQL statements and parameters
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type.descriptor.sql=trace
# Statistics
log4j.logger.org.hibernate.stat=debug
# 2nd Level Cache
log4j.logger.org.hibernate.cache=debug
###
# Hibernate >= 5.4.5
###
# basic log level for all messages
log4j.logger.org.hibernate=info
# SQL statements and parameters
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type.descriptor.sql=trace
# Statistics and slow queries
log4j.logger.org.hibernate.stat=debug
log4j.logger.org.hibernate.SQL_SLOW=info
# 2nd Level Cache
log4j.logger.org.hibernate.cache=debug
###
#Hibernate >= 6
###
# basic log level for all messages
log4j.logger.org.hibernate=info
# SQL statements and parameters
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.orm.jdbc.bind=trace
# Statistics and slow queries
log4j.logger.org.hibernate.stat=debug
log4j.logger.org.hibernate.SQL_SLOW=info
# 2nd Level Cache
log4j.logger.org.hibernate.cache=debug
<Configuration monitorInterval="60">
<Properties>
<Property name="log-path">PropertiesConfiguration</Property>
</Properties>
<Appenders>
<Console name="Console-Appender" target="SYSTEM_OUT">
<PatternLayout>
<pattern>
[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
</pattern>>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<!-- Hibernate before 5.4.5 -->
<Logger name="org.hibernate.SQL" level="debug" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.type.descriptor.sql" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.stat" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.cache" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<!-- Hibernate after 5.4.5 -->
<Logger name="org.hibernate.SQL" level="debug" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.type.descriptor.sql" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.stat" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.SQL_SLOW" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.cache" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<!-- Hibernate after 6 -->
<Logger name="org.hibernate.SQL" level="debug" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.orm.jdbc.bind" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.stat" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.SQL_SLOW" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Logger name="org.hibernate.cache" level="trace" additivity="false">
<AppenderRef ref="Console-Appender"/>
</Logger>
<Root level="info">
<AppenderRef ref="Console-Appender"/>
</Root>
</Loggers>
</Configuration>
###
# Global configuration for all Hibernate versions
###
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
org.hibernate.level=INFO
###
# Hibernate < 5.4.5
###
# basic log level for all messages
org.hibernate.SQL.level=FINER
org.hibernate.type.descriptor.sql.level=FINEST
# Statistics
org.hibernate.stat.level=FINER
# 2nd Level Cache
org.hibernate.cache.level=FINER
###
# Hibernate >= 5.4.5
###
# basic log level for all messages
org.hibernate.SQL.level=FINER
org.hibernate.type.descriptor.sql.level=FINEST
# Statistics
org.hibernate.stat.level=FINER
org.hibernate.SQL_SLOW.level=INFO
# 2nd Level Cache
org.hibernate.cache.level=FINER
###
# Hibernate >= 6
###
# basic log level for all messages
org.hibernate.SQL.level=FINER
org.hibernate.orm.jdbc.bind.level=FINEST
# Statistics
org.hibernate.stat.level=FINER
org.hibernate.SQL_SLOW.level=INFO
# 2nd Level Cache
org.hibernate.cache.level=FINER
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<Pattern>
%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
</Pattern>
</encoder>
</appender>
<!-- Hibernate before 5.4.5 -->
<logger name="org.hibernate.SQL" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.type.descriptor.sql" level="trace" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.stat" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.cache" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<!-- Hibernate after 5.4.5 -->
<logger name="org.hibernate.SQL" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.type.descriptor.sql" level="trace" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.stat" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.SQL_SLOW" level="info" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.cache" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<!-- Hibernate after 6 -->
<logger name="org.hibernate.SQL" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.orm.jdbc.bind" level="trace" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.stat" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.SQL_SLOW" level="info" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<logger name="org.hibernate.cache" level="debug" additivity="false">
<appender-ref ref="STDOUT"/>
</logger>
<root level="info">
<appender-ref ref="STDOUT"/>
</root>
</configuration>
If you use any of these configurations with Hibernate 4 or 5, it will write a log file that looks very similar to the following one. It was written by log4j2 and Hibernate 5. The log shows the Hibernate messages for a session in which I persisted 2 new Author entities, updated one of them afterward, and selected all Authors with a given last name.
13:45:20,863 DEBUG [org.hibernate.SQL] - select nextval ('hibernate_sequence')
13:45:20,907 DEBUG [org.hibernate.SQL] - select nextval ('hibernate_sequence')
13:45:20,939 DEBUG [org.hibernate.SQL] - insert into Author (firstName, lastName, version, id) values (?, ?, ?, ?)
13:45:20,950 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [VARCHAR] - [Thorben]
13:45:20,951 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [2] as [VARCHAR] - [Janssen]
13:45:20,952 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [3] as [INTEGER] - [0]
13:45:20,953 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [4] as [BIGINT] - [1]
13:45:20,960 DEBUG [org.hibernate.SQL] - insert into Author (firstName, lastName, version, id) values (?, ?, ?, ?)
13:45:20,960 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [VARCHAR] - [Nicolia]
13:45:20,960 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [2] as [VARCHAR] - [Parlog]
13:45:20,961 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [3] as [INTEGER] - [0]
13:45:20,961 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [4] as [BIGINT] - [2]
13:45:21,488 DEBUG [org.hibernate.SQL] - update Author set firstName=?, lastName=?, version=? where id=? and version=?
13:45:21,494 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [VARCHAR] - [Nicolai]
13:45:21,503 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [2] as [VARCHAR] - [Parlog]
13:45:21,505 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [3] as [INTEGER] - [1]
13:45:21,509 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [4] as [BIGINT] - [2]
13:45:21,510 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [5] as [INTEGER] - [0]
13:45:21,522 DEBUG [org.hibernate.SQL] - select author0_.id as id1_0_, author0_.firstName as firstNam2_0_, author0_.lastName as lastName3_0_, author0_.version as version4_0_ from Author author0_ where author0_.lastName=?
13:45:21,524 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [VARCHAR] - [Janssen]
13:45:21,531 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([id1_0_] : [BIGINT]) - [1]
13:45:21,541 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] - Session Metrics {
71600 nanoseconds spent acquiring 1 JDBC connections;
42200 nanoseconds spent releasing 1 JDBC connections;
5946500 nanoseconds spent preparing 6 JDBC statements;
9801200 nanoseconds spent executing 6 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;
55887200 nanoseconds spent executing 2 flushes (flushing a total of 4 entities and 0 collections);
27027800 nanoseconds spent executing 1 partial-flushes (flushing a total of 2 entities and 2 collections)
}
If you don’t need that much information, I recommend removing the configuration of the org.hibernate.type.descriptor.sql category. This will remove the log messages showing the bind parameter values. As you can see in the log file, these are the majority of the written log messages, and there are so many of them that the log gets hard to read.
As you can see in the following snippet, the log written by Hibernate 6 looks very similar. If you’re selecting multiple entity objects, it’s often a little easier to read than the log written by earlier Hibernate versions. That’s mostly because the category org.hibernate.orm.jdbc.bind only includes log messages for bind parameters but not for extracted parameters.
If you want to reduce the amount of information, you should consider deactivating trace logging for the category org.hibernate.orm.jdbc.bind.
15:37:21,600 DEBUG [org.hibernate.SQL] - select nextval('Author_SEQ')
15:37:21,609 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 2 milliseconds. SQL: 'select nextval('Author_SEQ')'
15:37:21,612 DEBUG [org.hibernate.SQL] - select nextval('Author_SEQ')
15:37:21,615 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 2 milliseconds. SQL: 'select nextval('Author_SEQ')'
15:37:21,902 DEBUG [org.hibernate.SQL] - insert into Author (firstName, lastName, version, id) values (?, ?, ?, ?)
15:37:21,903 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [1] as [VARCHAR] - [Thorben]
15:37:21,903 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [2] as [VARCHAR] - [Janssen]
15:37:21,903 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [3] as [INTEGER] - [0]
15:37:21,904 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [4] as [BIGINT] - [1]
15:37:21,908 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 4 milliseconds. SQL: 'insert into Author (firstName, lastName, version, id) values ('Thorben', 'Janssen', 0, 1)'
15:37:21,911 DEBUG [org.hibernate.SQL] - insert into Author (firstName, lastName, version, id) values (?, ?, ?, ?)
15:37:21,911 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [1] as [VARCHAR] - [Nicolia]
15:37:21,911 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [2] as [VARCHAR] - [Parlog]
15:37:21,912 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [3] as [INTEGER] - [0]
15:37:21,912 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [4] as [BIGINT] - [2]
15:37:21,914 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 2 milliseconds. SQL: 'insert into Author (firstName, lastName, version, id) values ('Nicolia', 'Parlog', 0, 2)'
15:37:21,915 DEBUG [org.hibernate.SQL] - update Author set firstName=?, lastName=?, version=? where id=? and version=?
15:37:21,915 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [1] as [VARCHAR] - [Nicolai]
15:37:21,915 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [2] as [VARCHAR] - [Parlog]
15:37:21,916 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [3] as [INTEGER] - [1]
15:37:21,916 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [4] as [BIGINT] - [2]
15:37:21,916 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [5] as [INTEGER] - [0]
15:37:21,919 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 3 milliseconds. SQL: 'update Author set firstName='Nicolai', lastName='Parlog', version=1 where id=2 and version=0'
15:37:21,952 DEBUG [org.hibernate.SQL] - select a1_0.id,a1_0.firstName,a1_0.lastName,a1_0.version from Author a1_0 where a1_0.lastName=?
15:37:21,952 TRACE [org.hibernate.orm.jdbc.bind] - binding parameter [1] as [VARCHAR] - [Janssen]
15:37:21,959 INFO [org.hibernate.SQL_SLOW] - SlowQuery: 6 milliseconds. SQL: 'select a1_0.id,a1_0.firstName,a1_0.lastName,a1_0.version from Author a1_0 where a1_0.lastName='Janssen''
15:37:21,964 DEBUG [org.hibernate.stat.internal.StatisticsImpl] - HHH000117: HQL: SELECT a FROM Author a WHERE a.lastName = :lastName, time: 26ms, rows: 1
15:37:21,972 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] - Session Metrics {
51899 nanoseconds spent acquiring 1 JDBC connections;
30200 nanoseconds spent releasing 1 JDBC connections;
419199 nanoseconds spent preparing 6 JDBC statements;
21482801 nanoseconds spent executing 6 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;
390499 nanoseconds spent executing 1 flushes (flushing a total of 2 entities and 2 collections);
40233400 nanoseconds spent executing 1 partial-flushes (flushing a total of 2 entities and 2 collections)
}
As long as you do not need to analyze an issue in production, you should log as little information as possible. This can be done for all Hibernate versions by setting all Hibernate-related log categories to ERROR. You should also make sure that the Hibernate statistics component and the slow query log are deactivated.
log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.Target=System.out log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] - %m%n log4j.rootLogger=info, stdout # basic log level for all messages log4j.logger.org.hibernate=error
<Configuration monitorInterval="60"> <Properties> <Property name="log-path">PropertiesConfiguration</Property> </Properties> <Appenders> <Console name="Console-Appender" target="SYSTEM_OUT"> <PatternLayout> <pattern> [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n </pattern>> </PatternLayout> </Console> </Appenders> <Loggers> <Logger name="org.hibernate" level="error" additivity="false"> <AppenderRef ref="Console-Appender"/> </Logger> <Root level="info"> <AppenderRef ref="Console-Appender"/> </Root> </Loggers> </Configuration>
handlers=java.util.logging.ConsoleHandler java.util.logging.ConsoleHandler.level=FINEST java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter org.hibernate.level=SEVERE
<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <Pattern> %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n </Pattern> </encoder> </appender> <logger name="org.hibernate" level="error" additivity="false"> <appender-ref ref="STDOUT"/> </logger> <root level="info"> <appender-ref ref="STDOUT"/> </root> </configuration>
Hibernate supports several logging providers and you can pick the one you prefer by adding it to the classpath of your application.
The log messages are grouped into different categories, and you can activate or deactivate them by assigning a log level for each category.
Writing log messages and collecting the required information takes some time. You should, therefore, switch off all unnecessary log messages in your production configuration.
The development configuration should activate debug logging for some crucial categories like org.hibernate.SQL and I most often also activate Hibernate statistics to find potential performance issues as soon as possible.