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:

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

Logger Information contained
org.hibernate.SQL SQL statements as they are passed to JDBC
org.hibernate.type.descriptor.sql Parameters which are bound to SQL statements (ie. WHERE clause)
org.hibernate.tool.hbm2ddl Data Definition Language statements (ie. CREATE TABLE)
org.hibernate.pretty State of entities associated with session at their flush time
org.hibernate.cache Hibernate’s second level cache activity
org.hibernate.hql.internal.ast.AST Messages from Hibernate Query Language parsing
org.hibernate All the Hibernate log messages. Very large volume of log messages

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.

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

    @OneToMany(cascade = CascadeType.ALL)
    @JoinColumn(name = "RECEIPT_ID")
    private Set lineItems;
//staic factory method

@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;

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

public void whenPersist_thenIdIsAssigned() {
    LineItem strawberries = LineItem.getBuilder()
    LineItem yoghurt = LineItem.getBuilder()

    Set lineItemsSet = new HashSet<>();
    Receipt receipt = Receipt.newInstance(, lineItemsSet);

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.

3 comments add yours

  1. Hi Adam
    Thank you for the nice article. I’ve been considering if it is possible to log parameters of executed SQL statements as well (marked as ‘?’ in the log). I would love the feature :)
    BTW regarding the inserting and updating the same LINE_ITEM. I’ve not tested it but my guess is: when entity manager inserts LineItem entity couldn’t fill the receiptId because the entity class doesn’t have it. Just later it adds the reference to receipt. Enriching LineItem class by receiptId can help here.

    • Hey Marek,
      thanks so much for the comment, I’m really glad you liked the article.
      Yes, it certainly is possible to see what parameters are bound to SQL statements. You do it with the following logger:

      name=”org.hibernate.type.descriptor.sql” level=”trace” additivity=”false”

      For this example I purposely removed it, because I wanted us to focus on the SQL queries being logged. When you use the log4j setup in article example you’ll have it :)
      This is how it looks like:

      17:01:58.748 [main] DEBUG org.hibernate.SQL – insert into RECEIPT (id, TRANSACTION_DATE) values (null, ?)
      17:01:58.754 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder – binding parameter [1] as [TIMESTAMP] – [2019-01-09T17:01:58.647]

      For your Second point, yes you’re completely right, when LineItem has a reference to Receipt, it does not need an additional update query.
      When you want the LineItem list in Receipt to be immutable this two way mapping creates a problem. When you add a @ManyToOne field in LineItem, you need to change the annotation in Receipt a little, by adding a mappedBy, just like that

      @OneToMany(cascade = CascadeType.ALL, mappedBy = “receipt”)
      private Set lineItems;

      Now this will cause LineItem to be the owner of the relation. This means in order to have Foreign Key properly set in LINE_ITEM table (line item pointing to correct receipt) you need to set the receipt field in LineItem. Otherwise the foreign key column will be null.
      This means that you’ll need to create Receipt instance first with empty lineItems collection, then create each LineItem and set their receipt field to the created instance. Things will be persisted fine, but Receipt.lineItems is supposed to be an immutable set. It’s empty in memory, but it’s actually not empty in the database, cause LineItems have a reference to created Receipt.

      • Thank you very much for the extended explanation regarding entity reference and immutability.
        Logging sql parameters with statements – fabulous.

Leave a Comment