Hibernate Logging and Statistics

This article cover how to do logging in Hibernate with SLF4j + Log4j logging framework. You also see the use of Show_sql , Format_sql and Use_sql_comments.

You’ve seen the hibernate.show_sql configuration property in our many articles. You’ll need it continually when you develop software with Hibernate; it enables logging of all generated SQL to the console. You’ll use it for troubleshooting, for performance tuning, and to see what’s going on. If you also enable hibernate.format_sql, the output is more readable but takes up more screen space. A third option you haven’t set so far is hibernate.use_sql_comments – it causes Hibernate to put comments inside all generated SQL statements to hint at their origin. For example, you can then easily see if a particular SQL statement was generated from an explicit query or an on-demand collection initialization.

First create a new Java Project and configure it as Maven Project. For Reference, Click Here

Add the following dependencies in pom.xml

<dependencies>
 
    <dependency>
        <groupId>junit</groupId>
        <artifactId>junit</artifactId>
        <version>4.8.2</version>
        <scope>test</scope>
    </dependency>
 
    <dependency>
        <groupId>mysql</groupId>
        <artifactId>mysql-connector-java</artifactId>
        <version>5.1.15</version>
    </dependency>
 
    <dependency>
        <groupId>org.hibernate</groupId>
        <artifactId>hibernate-core</artifactId>
        <version>3.6.3.Final</version>
    </dependency>
    <dependency>
        <groupId>org.hibernate</groupId>
        <artifactId>hibernate-c3p0</artifactId>
        <version>4.1.7.Final</version>
    </dependency>
    <dependency>
        <groupId>javassist</groupId>
        <artifactId>javassist</artifactId>
        <version>3.12.1.GA</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>1.6.6</version>
    </dependency>
</dependencies>

1. Show_sql

Enable the logging of all the generated SQL statements to the console.

<property name="show_sql">true</property>

Output is :

Hibernate: insert into EMPLOYEE (NAME) values (?)

2. Format_sql

If you also enable hibernate.format_sql, the output is more readable but takes up more screen space

<property name="format_sql">true</property>

Output is :

Hibernate: 
    insert 
    into
        EMPLOYEE
        (NAME) 
    values
        (?)

3. Use_sql_comments

It causes Hibernate to put comments inside all generated SQL statements to hint at their origin.

<property name="use_sql_comments">true</property>

Output is :

Hibernate: 
    /* insert com.kruders.bean.Employee
        */ insert 
        into
            EMPLOYEE
            (NAME) 
        values
            (?)

4. Log4j

Hibernate logs all interesting events through Apache commons-logging, a thin abstraction layer that directs output to either Apache Log4j (if you put log4j.jar in your classpath) or JDK 1.4 logging (if you’re running under JDK 1.4 or above and Log4j isn’t present). We recommend Log4j because it’s more mature, more popular, and under more active development.

To see output from Log4j, you need a file named log4j.properties in your classpath (right next to hibernate.properties or hibernate.cfg.xml). Also, don’t forget to copy the log4j.jar library to your lib directory. The Log4j configuration example in listing 1.1 directs all log messages to the console and a file.

Listing below shows an example log4j.properties configuration file

# Direct log messages to stdout
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{ABSOLUTE} %5p %c{1}:%L - %m%n
 
# Direct log messages to a log file
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=C:\\HibernateLogging.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
 
# Root logger option
log4j.rootLogger=INFO, stdout, file
# Hibernate logging options (INFO only shows startup messages)
log4j.logger.org.hibernate=INFO
 
# Log JDBC bind parameter runtime arguments
log4j.logger.org.hibernate.type=INFO

The last category in this configuration file is especially interesting: It enables the logging of JDBC bind parameters if you set it to DEBUG level, providing information you usually don’t see in the ad hoc SQL console log.

5. Run Program

Create Main.java class and run it as Java Application

package com.kruders.core;

import org.hibernate.HibernateException;
import org.hibernate.Session;
import org.hibernate.SessionFactory;
import org.hibernate.Transaction;
import org.hibernate.cfg.AnnotationConfiguration;

import com.kruders.bean.Employee;
import com.kruders.util.HibernateUtil;

public class Main {
	public static void main(String args[]) throws InterruptedException {
		Session session = HibernateUtil.getSessionFactory().openSession();
		Transaction transaction = null;
        try {
        	transaction = session.beginTransaction();
            
            Employee employee = new Employee("Puneet");
            session.save(employee);
          
            transaction.commit();
        }catch (HibernateException e) {
            transaction.rollback();
            e.printStackTrace();
        } finally {
            session.close();
        }
         
       
    }
}

You will see the following output as shown in Figure 15.1

Figure 15.1

HibernateLogging.log file will be created under C:\

It contains the similar content as shown below.

12:08:09,515  INFO Configuration:2270 - Configured SessionFactory: null
12:08:09,578  INFO AnnotationBinder:532 - Binding entity from annotated class: com.kruders.bean.Employee
12:08:09,609  INFO EntityBinder:530 - Bind entity com.kruders.bean.Employee on table EMPLOYEE
12:08:09,640  INFO Configuration:1649 - Hibernate Validator not found: ignoring
12:08:09,640  INFO HibernateSearchEventListenerRegister:75 - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.
12:08:09,640  INFO DriverManagerConnectionProvider:64 - Using Hibernate built-in connection pool (not for production use!)
12:08:09,640  INFO DriverManagerConnectionProvider:65 - Hibernate connection pool size: 1
12:08:09,640  INFO DriverManagerConnectionProvider:68 - autocommit mode: false
12:08:09,656  INFO DriverManagerConnectionProvider:103 - using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/test
12:08:09,656  INFO DriverManagerConnectionProvider:109 - connection properties: {user=root, password=****}
12:08:09,843  INFO Dialect:135 - Using dialect: org.hibernate.dialect.MySQLDialect
12:08:09,843  INFO SettingsFactory:126 - Database ->
       name : MySQL
    version : 5.5.24
      major : 5
      minor : 5
12:08:09,843  INFO SettingsFactory:132 - Driver ->
       name : MySQL-AB JDBC Driver
    version : mysql-connector-java-5.1.15 ( Revision: ${bzr.revision-id} )
      major : 5
      minor : 1
12:08:09,843  INFO TransactionFactoryFactory:59 - Using default transaction strategy (direct JDBC transactions)
12:08:09,843  INFO TransactionManagerLookupFactory:80 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
12:08:09,843  INFO SettingsFactory:179 - Automatic flush during beforeCompletion(): disabled
12:08:09,843  INFO SettingsFactory:183 - Automatic session close at end of transaction: disabled
12:08:09,843  INFO SettingsFactory:190 - JDBC batch size: 15
12:08:09,843  INFO SettingsFactory:193 - JDBC batch updates for versioned data: disabled
12:08:09,843  INFO SettingsFactory:198 - Scrollable result sets: enabled
12:08:09,843  INFO SettingsFactory:206 - JDBC3 getGeneratedKeys(): enabled

The folder structure of the example is shown below in Figure 15.2

Figure 15.2