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}
