Logging Hibernate SQL statements with Log4j

The following article shows how to configure logging with log4j2 and Hibernate. Enabling logging helps visualize SQL statements which Hibernate uses to communicate with the database. It’s a great way to debug the application and discover sub-optimal queries, N+1 selects or Cartesian product problems. You can find the code to below examples on Github.

Hibernate’s JBoss Logging bridge

Before we learn to set things up, here are few technicalities.
Hibernate does not ship with a logging framework dependency. It uses a logging bridge instead.
Logging bridge (or facade) is an abstraction layer providing logging API and allowing to attach the desired logging framework at deploy time. Similarly to JPA, it provides a set of classes allowing to log messages with any desired logging library you decide to use.
Since version 4.0 Hibernate stopped using Slf4j as its default logging bridge and started using JBoss Logging instead. Since JBoss Logging is added as a dependency in Hibernate, you can consider using it in your application.
There’s one word of caution however. JBoss Logging API is very poorly documented. It’s really hard to discover how to effectively bind parameters to log messages or avoid double log level checking. The only sources, describing JBoss Logging I was able to find on the web are the following:

• Hibernate documentation
• JBoss Logging documentation
• Red Hat documentation

In case of JBoss Logging, there is a big tradeoff between benefits of logging facade and its usability. Due to that I decided to strongly couple the example application with Log4j2, which contains numerous optimizations and is well documented. In other words, I ditched JBoss Logging bridge. I’d probably never use it in a live appliaction due to its poor documentation.

Adding pom.xml dependencies

Setting up log4j2.xml

Log4j configuration file needs to be placed in application classpath. There are several file formats you can choose from, like .xml, .properties, .yaml and more.

Above code configures three custom loggers: one for classes in com.allaroundjava package, one for org.hibernate.SQL and one for org.hibernate.type.descriptor.sql. Here’s what information you can extract with particular loggers.

Information in Hibernate Loggers

Observing log messages

At this moment you should have Log4j configured and can enjoy viewing Hibernate log messages in application console. You can use the above code as a template.

The below code shows how Hibernate log messages look in practice. Take a look at below entity hierarchy and logged SQL statements. Classes come from previous article on Hibernate immutability, take a look there to understand what the @Immutable annotation does.
Entities in below example, are in single-sided one to many relation with Receipt carrying cascade on all operations. To see full code, please go to allaroundjava Github.

@Entity
@Table(name = "RECEIPT")
@org.hibernate.annotations.Immutable
public final class Receipt extends ModelBase {
    @Column(nullable = false, name = "TRANSACTION_DATE")
    private LocalDateTime transactionDate;

    @OneToMany(cascade = CascadeType.ALL)
    @JoinColumn(name = "RECEIPT_ID")
    @org.hibernate.annotations.Immutable
    private Set lineItems;
//constructor
//getters
//staic factory method

@Entity
@Table(name = "LINE_ITEM")
public final class LineItem extends ModelBase{
    @Column(name = "ITEM_NAME", nullable = false)
    private String itemName;
    @Column(nullable = false)
    private BigDecimal price;
    @Column(nullable = false)
    private int quantity;
//constructor
//getters
//builder

Let’s see how Receipt persistence works in the background with this simple test.

@Test
public void whenPersist_thenIdIsAssigned() {
    LineItem strawberries = LineItem.getBuilder()
            .withItemName("strawberries")
            .withPrice(BigDecimal.TEN)
            .withQuantity(3)
            .build();
    LineItem yoghurt = LineItem.getBuilder()
            .withItemName("yoghurt")
            .withPrice(BigDecimal.ONE)
            .withQuantity(2)
            .build();

    Set lineItemsSet = new HashSet<>();
    lineItemsSet.add(strawberries);
    lineItemsSet.add(yoghurt);
    Receipt receipt = Receipt.newInstance(LocalDateTime.now(), lineItemsSet);
    receiptDao.persist(receipt);
    Assert.assertNotNull(receipt.getId());
}

Above code results in the following SQL statements being generated and sent to the database. This is an output from a single Hibernate logger called org.hibernate.SQL

19:23:59.468 [main] DEBUG org.hibernate.SQL - insert into RECEIPT (id, TRANSACTION_DATE) values (null, ?)
19:23:59.475 [main] DEBUG org.hibernate.SQL - insert into LINE_ITEM (id, ITEM_NAME, price, quantity) values (null, ?, ?, ?)
19:23:59.475 [main] DEBUG org.hibernate.SQL - insert into LINE_ITEM (id, ITEM_NAME, price, quantity) values (null, ?, ?, ?)
19:23:59.486 [main] DEBUG org.hibernate.SQL - update LINE_ITEM set RECEIPT_ID=? where id=?
19:23:59.497 [main] DEBUG org.hibernate.SQL - update LINE_ITEM set RECEIPT_ID=? where id=?

Interestingly each LINE_ITEM requires two SQL statements – an insert and an update. This is not something we would intuitively expect and may be a reason for application performing badly when running a large number of such operations. It’s definitely worth looking into when batch or high-speed event processing.