hibernate

How to solve some of the most common Hibernate issues with proper logging?

Hibernate’s logging configuration is an important but rarely discussed topic. The right configuration can help you to find potential issues during development while a wrong configuration can cause serious performance problems in production. That’s one of the reasons why I explain different configuration options in my new book Hibernate Tips: More than 70 solutions to common Hibernate problems.

In this post, we’ll share 2 of the most useful Hibernate logging tips from the book. Let’s get started.

1. Solving the most common Hibernate performance problem

Let’s take a look at one of the recipes included in the book. It helps you to find n+1 select issues during development. This performance problem often occurs when Hibernate has to initialize lazily fetched associations between entities. Unfortunately, this issue is hard to find in the source code because you just call the getter method of an attribute that maps the association, like author.getBooks(). If you do this in a loop that iterates through a List of Author entities, Hibernate has to perform 1 query to load n Author entities and n additional queries to initialize the association. That is called the n+1 select issue, and it’s one of the most common performance problems.

You can find it by activating Hibernate`s Statistics component which provides an easy way to count all executed queries in your Hibernate Session. Let’s see how it’s done.

How to count the executed queries in a Session

Problem

Some of my use cases are slow and seem to perform too many queries.

How do I count all queries executed within a Hibernate Session?

Solution

The easiest way to count all executed queries is to activate Hibernate’s statistics component. Hibernate then collects a lot of internal statistics and provides them as a log message and via the Statistics API.

WARNING: Do not use this in production! Collecting the statistical information creates an overhead that slows down your application.

Hibernate’s statistics component is deactivated by default. You can activate it by setting the hibernate.generate_statistics parameter to true. You can either do this by providing a system property with the same name or by setting the parameter in the persistence.xml file.

You have two options to access the statistics. Hibernate can write a subset with the most important information of each session to the log file or you can access them via the Statistics API.

Let’s take a look at the log messages first. Hibernate writes a log message, similar to the following one, at the end of each session. It shows the number of SQL statements, the time spent for their preparation and execution and the interaction with the second-level cache.

You can also access the Statistics API via Hibernate’s Statistics interface. You can get it from the SessionFactory. It provides several getter methods that give you access to more detailed information than the log output.

Source Code

You can find a download link for a project with executable test cases for this Hibernate tip in the book.

Learn more

If you want to learn more about Hibernate’s logging features, you should have a look at chapters:

  • How to log SQL statements and their parameters
  • How to use query comments to identify a query

=============

Counting the executed queries can help find inefficiencies and avoid performance problems. But that’s not enough. You also need to know which queries Hibernate executes and which parameter values it uses. With the correct logging configuration, Hibernate will write all of that information to the log.

=============

2. How to log SQL statements and their parameters

Problem

How do you configure Hibernate so that it writes the executed SQL statements and used bind parameters to the log file?

Solution

Hibernate uses two different log categories and log levels to log the executed SQL statements and their bind parameters:

  • The SQL statements are written as DEBUG messages to the category org.hibernate.SQL.
  • The bind parameter values are logged to the org.hibernate.type.descriptor.sql category with log level TRACE.

You can activate and deactivate them independently of each other in your log configuration.

WARNING: Logging all SQL queries and their bind parameter bindings can slow down your application and create huge log files.

You shouldn’t activate these log messages in production.

The following code snippet shows an example of a log4j configuration which activates both of them.

Hibernate then writes log messages like the following ones to your log file.

The SQL statement in the code snippet isn’t easy to read. That gets a lot better when you tell Hibernate to format it.

You can do that by setting the configuration parameter hibernate.format_sql to true. You can provide it as a system property or set it in the persistence.xml file, like in the following code snippet, or in the hibernate.cfg.xml file.

The following code snippet shows the formatted SQL statement which is much better to read than the previous message.

Source Code

You can find a download link for a project with executable test cases for this Hibernate tip in the book.

Making your logs better

As mentioned, activating TRACE and DEBUG level messages and sending them to your log could lead to huge files, and might even slow down your application. However, they might hold pieces of information that’s critical for the debugging process, and could help identify critical errors before they hit production.

OverOps shows you the last 250 DEBUG, TRACE and INFO level statements that were logged prior to the error, in production, even if they were turned off and never reached the log file. It also shows the variable state behind any exception, logged error or warning, without relying on the information that was actually logged. You can see the complete source code and variable state across the entire call stack of the error, even across microservices and machines.

Discover the new way to debug errors in production. Watch a live demo of OverOps.

OverOps

Conclusion

For more recipes like this, check out my new book Hibernate Tips: More than 70 solutions to common Hibernate problems. It gives you more than 70 ready-to-use recipes for topics like basic and advanced mappings, logging, Java 8 support, caching and statically and dynamically defined queries.

email
Thorben Janssen is an independent trainer and author with more than 15 years of experience in Java and Java EE. He works as a senior developer and software architect, is a member of the CDI 2.0 expert group (JSR 365) and writes about Java EE related topics on his blog www.thoughts-on-java.org