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 logs as fewer messages as possible and avoids any overhead.
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:
- JBoss LogManager
- Log4j 2
- Log4j 1
- JDK logging
You just need to add your preferred framework to your 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 personally 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 names of the log level might be different if you use a different framework.
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:
|org.hibernate||This category contains all messages written by Hibernate. You can use this to analyze unspecific issues or to find categories used by Hibernate.
Be careful, 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 log category.
You can use it together with org.hibernate.type.descriptor.sql to get more information about the JDBC parameters and results.
|org.hibernate.type.descriptor.sql||Hibernate writes the values bound to the JDBC parameters and extracted from the JDBC results to this log category.
This category should be used together with org.hibernate.SQL to also log the SQL statements.
|org.hibernate.pretty||Hibernate logs the state at flush time of max. 20 entities to this log category.|
|org.hibernate.cache||Information about second level cache activities is written to this log 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||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 define 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. Activating the statement logging like this has two big disadvantages:
- 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 and writing to standard out is most often much slower than using an optimized logging framework.
- 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, I want to know what Hibernate is doing in the background. But logging these information slows down the application and they are not required in production. I therefore recommend to use two different settings:
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 I personally prefer to also activate Hibernate statistics to get a summary of the most important metrics at the end of the session.
The following snippet shows the Hibernate messages for a session in which I persisted 2 new Author entities, updated one of them afterwards and selected all Authors with a given last name.
If you need more information, you can also set org.hibernate.type.descriptor.sql to TRACE to see the values bound to the JDBC parameters and extracted from the result and org.hibernate.stat to DEBUG to get statistical information about each query.
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.
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 me 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 and get an early bird discount until 2016/01/31.