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.
<persistence>
<persistence-unit name="my-persistence-unit">
<description>Hibernate Tips</description>
<provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>
<properties>
<property name="hibernate.generate_statistics" value="true" />
…
</properties>
</persistence-unit>
</persistence>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.
16:24:55,318 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] – Session Metrics {
25659 nanoseconds spent acquiring 1 JDBC connections;
22394 nanoseconds spent releasing 1 JDBC connections;
1091216 nanoseconds spent preparing 12 JDBC statements;
11118842 nanoseconds spent executing 12 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;
16999942 nanoseconds spent executing 1 flushes (flushing a total of 17 entities and 17 collections);
63915 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)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.
Statistics stats = sessionFactory.getStatistics(); long queryCount = stats.getQueryExecutionCount(); long collectionFetchCount = stats.getCollectionFetchCount();
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.
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=traceHibernate then writes log messages like the following ones to your log file.
17:34:50,353 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_.id=1 17:34:50,362 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([id1_0_] : [BIGINT]) - [1] 17:34:50,373 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([firstNam2_0_] : [VARCHAR]) - [Thorben] 17:34:50,373 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([lastName3_0_] : [VARCHAR]) - [Janssen] 17:34:50,374 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([version4_0_] : [INTEGER]) - [0]
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.
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<persistence>
<persistence-unit name="my-persistence-unit">
<description>Hibernate Tips</description>
<provider>
org.hibernate.jpa.HibernatePersistenceProvider
</provider>
<exclude-unlisted-classes>false</exclude-unlisted-classes>
<properties>
<property name="hibernate.format_sql" value="true" />
...
</properties>
</persistence-unit>
</persistence>The following code snippet shows the formatted SQL statement which is much better to read than the previous message.
16:42:56,873 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_.id=?
16:42:56,926 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] - binding parameter [1] as [BIGINT] - [1]
16:42:56,950 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([id1_0_] : [BIGINT]) - [1]
16:42:56,965 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([firstNam2_0_] : [VARCHAR]) - [Thorben]
16:42:56,965 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([lastName3_0_] : [VARCHAR]) - [Janssen]
16:42:56,966 TRACE [org.hibernate.type.descriptor.sql.BasicExtractor] - extracted value ([version4_0_] : [INTEGER]) - [0]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.
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. For just a few days, you can get the ebook for $2.99 and the paperback for $12.99 on hibernate-tips.com.
| Reference: | Hibernate Logging: Tips and Solutions to Common Problems from our JCG partner at the OverOps blog. |
