Hibernate Logging Options

For years I have relied on a simple property "show-sql=true" to see Hibernate's generated SQL. This option is fairly limited:

  • it bypasses the logging framework in the rest of my apps (SLF4J)
  • it doesnt show parameters, just question marks
  • it doesn't show any timing information

Frustrated at these limitations, I set out to understand all of the other options available to me. This is very likely not a complete list.

  • Spring 4.1.7.Release
  • Hibernate 4.3.8.Final
  • slf4j 1.7.11

Plain show-sql

Properties

  • hibernate.show-sql=true
insert into address (is_active, address, city, country, county, created_date, external_key, postal_code, state, modified_date) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

select this_.id as id1_0_1_, this_.is_active as is_activ2_0_1_, this_.address as address3_0_1_, this_.city as city4_0_1_, ... from address this_ where this_.external_key=? and this_.is_active=?

If you have org.hibernate.SQL set to DEBUG in your logging configuration, you will see output twice - once by System.out calls, once by a call to the logging framework. So, if you are using a logging framework, it is recommended that you do not use this setting

show-sql plus hibernate.format_sql

Properties:

  • hibernate.format_sql=true
  • hibernate.show-sql=true

With Spring Boot:

  • spring.jpa.properties.hibernate.format_sql=true
  • spring.jpa.properties.hibernate.show-sql=true
    insert 
    into
        address
        (is_active, address, city, country, county, created_date, external_key, postal_code, state, modified_date) 
    values
        (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
--
    select
        this_.id as id1_0_1_,
        this_.is_active as is_activ2_0_1_,
        this_.address as address3_0_1_,
        this_.city as city4_0_1_,
        ...

    from
        address this_ 
  
    where
        this_.external_key=? 
        and this_.is_active=?



Show Database Stats

These settings show two different statistics. First, HQL queries are show with a total time consumed, and the number of rows returned. Secondly, metrics for the entire session, including time spent acquiring a connecting, preparing statements, executing statements, and flushing data.

Properties:

  • hibernate.generate_statistics=true

<logger name="org.hibernate.stat" level="DEBUG"/>

With Spring Boot:

  • spring.jpa.properties.hibernate.generate_statistics=true
  • logging.level.org.hibernate.stat=DEBUG
20:01:36.527 [main] DEBUG o.h.s.i.ConcurrentStatisticsImpl - HHH000117: HQL: from com.bla.address.model.AddressEntity where externalKey=:fieldValue, time: 1ms, rows: 1

20:14:03.812 [main] INFO o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
29048614 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
621215 nanoseconds spent preparing 3 JDBC statements;
27612555 nanoseconds spent executing 3 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;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
31164000 nanoseconds spent executing 2 partial-flushes (flushing a total of 2 entities and 2 collections)

Show SQL Parameters

<logger name="org.hibernate.type.descriptor.sql" level="TRACE"/>

With Spring Boot:

  • logging.level.org.hibernate.type.descriptor.sql=TRACE
20:09:09.518 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [BOOLEAN] - [true]
20:09:09.519 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - [123 Fake St]
20:09:09.520 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [3] as [VARCHAR] - [null]
20:09:09.520 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [4] as [VARCHAR] - [null]
20:09:09.520 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [5] as [VARCHAR] - [null]
20:09:09.522 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [6] as [TIMESTAMP] - [2015-10-23 20:09:09.432]
20:09:09.523 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [7] as [VARCHAR] - [KEY123]
20:09:09.523 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [8] as [VARCHAR] - [null]
20:09:09.524 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [9] as [VARCHAR] - [null]
20:09:09.524 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [10] as [TIMESTAMP] - [2015-10-23 20:09:09.473]
20:09:09.855 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [KEY123]
20:09:09.856 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [2] as [BOOLEAN] - [true]

20:09:09.905 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([id1_1_0_] : [INTEGER]) - [null]
20:09:09.906 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([id1_0_1_] : [INTEGER]) - [12]
20:09:09.906 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([address10_0_3_] : [INTEGER]) - [null]

20:09:10.314 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [KEY123]
20:09:10.316 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([id1_0_] : [INTEGER]) - [12]

Show Entities on Flush

<logger name="org.hibernate.pretty" level="ALL"/> <-- this doesnt appear to have any effect
<logger name="org.hibernate.event.internal.AbstractFlushingEventListener" level="DEBUG"/>
<logger name="org.hibernate.internal.util.EntityPrinter" level="DEBUG"/>

With Spring Boot:

  • logging.level.org.hibernate.event.internal.AbstractFlushingEventListener=DEBUG
  • logging.level.org.hibernate.internal.util.EntityPrinter=DEBUG
20:29:12.544 [main] DEBUG org.hibernate.SQL - insert into address (is_active, address, city, country, county, created_date, external_key, postal_code, state, modified_date) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
20:29:12.750 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Processing flush-time cascades
20:29:12.753 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Dirty checking collections
20:29:12.759 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
20:29:12.759 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 2 (re)creations, 0 updates, 0 removals to 2 collections
20:29:12.849 [main] DEBUG o.h.internal.util.EntityPrinter - Listing entities:
20:29:12.850 [main] DEBUG o.h.internal.util.EntityPrinter - com.bla.address.model.AddressEntity{country=null, address=123 Fake St, city=null, postalCode=null, county=null, active=true,  tags=[], createdAt=2015-10-23T20:29:12.481-05:00, externalKey=KEY123, id=24, state=null, updatedAt=2015-10-23T20:29:12.514-05:00}
20:29:12.856 [main] DEBUG org.hibernate.SQL - select this_.id as id1_0_1_, this_.is_active as is_activ2_0_1_, this_.address as address3_0_1_, this_.city as city4_0_1_, ... from address this_ where this_.external_key=? and this_.is_active=?
20:29:13.162 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Processing flush-time cascades
20:29:13.163 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Dirty checking collections
20:29:13.163 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
20:29:13.163 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 2 (re)creations, 0 updates, 0 removals to 2 collections
20:29:13.164 [main] DEBUG o.h.internal.util.EntityPrinter - Listing entities:
20:29:13.164 [main] DEBUG o.h.internal.util.EntityPrinter - com.bla.address.model.AddressDo{country=null, address=123 Fake St, city=null, postalCode=null, county=null, active=true, tags=[], createdAt=2015-10-23T20:29:12.481-05:00, externalKey=KEY123, id=24, state=null, updatedAt=2015-10-23T20:29:12.514-05:00}
20:29:13.169 [main] DEBUG org.hibernate.SQL - select addressdo0_.id as id1_0_, addressdo0_.is_active as is_activ2_0_, addressdo0_.address as address3_0_, addressdo0_.city as city4_0_, addressdo0_.country as country5_0_, addressdo0_.county as county6_0_, addressdo0_.created_date as created_7_0_, addressdo0_.external_key as external8_0_, addressdo0_.postal_code as postal_c9_0_, addressdo0_.state as state10_0_, addressdo0_.modified_date as modifie11_0_ from address addressdo0_ where addressdo0_.external_key=?
20:29:13.172 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Processing flush-time cascades
20:29:13.172 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Dirty checking collections
20:29:13.173 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
20:29:13.173 [main] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 2 (re)creations, 0 updates, 0 removals to 2 collections
20:29:13.173 [main] DEBUG o.h.internal.util.EntityPrinter - Listing entities:
20:29:13.173 [main] DEBUG o.h.internal.util.EntityPrinter - com.bla.address.model.AddressDo{country=null, address=123 Fake St, city=null, postalCode=null, county=null, active=true, tags=[], createdAt=2015-10-23T20:29:12.481-05:00, externalKey=KEY123, id=24, state=null, updatedAt=2015-10-23T20:29:12.514-05:00}

 

Leave a Reply