Hibernate Logging Guide – Use the right config for development and production

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:

• A development configuration which logs enough internal information to understand the database interactions, see the number of executed queries and check the SQL statements.
• A production configuration which avoids any overhead by logging as few messages as possible.

Don’t want to read? You can watch it here!

Supported logging back-ends

Before we have a 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:

1. JBoss LogManager
2. Log4j 2
3. Log4j 1
4. Slf4j
5. JDK logging

You only need to add your preferred framework to the classpath, and the JBoss Logging library will pick it up. If there are multiple frameworks available, the one with the highest priority will be chosen.

I prefer log4j 2 and will use it for the examples in this post. The concepts and log categories are the same for all frameworks, but the format of the configuration file and the names of the log level 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.

Log categories

As 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:

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.

Don’t use show_sql to log SQL queries

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:

1. Hibernate writes all executed SQL statements to standard out without using the logging framework. Therefore, it becomes difficult to define the log file which shall contain these specific log messages. Writing to standard out is also most often much slower than using an optimized logging framework.
2. The persistence.xml is part of a jar file of your application, and you need to open that binary if you want to activate or deactivate the logging of the SQL statements. The configuration of your logging framework is most often an external text file that can be easily changed on any system.

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).

Recommended logging configurations

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:

Development

Hibernate is doing a lot of things for you in the background, and that 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.

To get this information, you need to set the log level for the org.hibernate.SQL category to DEBUG, and if you also want to log the used bind parameter values, you also need to set the org.hibernate.type.descriptor.sql category 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.

In the following sections, you can see such a logging configuration for different logging frameworks.

Log4J

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=info

# SQL statements and parameters
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type.descriptor.sql=trace

Log4J2

<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.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>
        <Root level="info">
            <AppenderRef ref="Console-Appender"/>
        </Root>
    </Loggers>
</Configuration>

JDK logger

handlers=java.util.logging.ConsoleHandler

java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

org.hibernate.level=INFO
org.hibernate.SQL.level=FINER
org.hibernate.type.descriptor.sql.level=FINEST

Logback via Slf4j

<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.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>
	<root level="info">
		<appender-ref ref="STDOUT"/>
	</root>
</configuration>

If you use any of these configurations, Hibernate will write a log file that looks very similar to the following one. It was written by log4j, and it 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 many information, I recommend starting with 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 read.

Production

As long as you do not need to analyze an issue in production, you should log as less information as possible. This can be done by setting all Hibernate related log categories to ERROR. You should also make sure that the Hibernate statistics component is deactivated.

Log4J

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

Log4J2

<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>

JDK logger

handlers=java.util.logging.ConsoleHandler

java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

org.hibernate.level=SEVERE

Logback via Slf4j

<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>

Summary

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.

If you like to learn more about finding and solving Hibernate related performance issues, have a look at my Hibernate Performance Tuning Training.