Hibernate Show SQL
When you are developing Spring Boot applications with database interactions, you typically use Hibernate as the Object Relationship Mapping (ORM) tool.
Instead of directly coupling your code with Hibernate, often, you'd rather use Spring Data JPA, a Spring Framework project.
Spring Data JPA makes the implementation of the data access layer incredibly easy by abstracting most of the complexities involved in persisting data.
Often, when you are working with Hibernate and Spring Data JPA, you will need to see what is happening under the hood. It is very helpful to see the actual SQL statements being generated by Hibernate.
Due to the nature of the abstractions offered by Hibernate and Spring Data JPA, it's very easy to inadvertently create n+1 queries — which is very detrimental to the performance of your application.
In this post, I'll share a tip on how to configure Hibernate and Spring Data JPA to log executed SQL statements and used bind parameters.
The Application
For the purpose of this post, I've created a simple Spring Boot application. In this application, we can perform CRUD operations on a Product entity.
Here is the Product entity.
Product.java:
package guru.springframework.domain;
import javax.persistence.*;
import java.math.BigDecimal;
@Entity
public class Product {
@Id
@GeneratedValue(strategy = GenerationType.AUTO)
private Integer id;
@Version
private Integer version;
private String productId;
private String description;
private String imageUrl;
private BigDecimal price;
public String getDescription() {
return description;
}
public void setDescription(String description) {
this.description = description;
}
public Integer getVersion() {
return version;
}
public void setVersion(Integer version) {
this.version = version;
}
public Integer getId() {
return id;
}
public void setId(Integer id) {
this.id = id;
}
public String getProductId() {
return productId;
}
public void setProductId(String productId) {
this.productId = productId;
}
public String getImageUrl() {
return imageUrl;
}
public void setImageUrl(String imageUrl) {
this.imageUrl = imageUrl;
}
public BigDecimal getPrice() {
return price;
}
public void setPrice(BigDecimal price) {
this.price = price;
}
}Below is a JUnit test class to save and retrieve products.
If you are new to JUnit, I'd suggest checking out my JUnit series of posts.
ProductRepositoryTest.java:
package guru.springframework.repositories;
import guru.springframework.configuration.RepositoryConfiguration;
import guru.springframework.domain.Product;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
import java.math.BigDecimal;
import static org.junit.Assert.*;
@RunWith(SpringJUnit4ClassRunner.class)
@SpringBootTest(classes = {RepositoryConfiguration.class})
public class ProductRepositoryTest {
private ProductRepository productRepository;
@Autowired
public void setProductRepository(ProductRepository productRepository) {
this.productRepository = productRepository;
}
@Test
public void testSaveProduct(){
//setup product
Product product = new Product();
product.setDescription("Spring Framework Guru Shirt");
product.setPrice(new BigDecimal("18.95"));
product.setProductId("1234");
//save product, verify has ID value after save
assertNull(product.getId()); //null before save
productRepository.save(product);
assertNotNull(product.getId()); //not null after save
//fetch from DB
Product fetchedProduct = productRepository.findOne(product.getId());
//should not be null
assertNotNull(fetchedProduct);
//should equal
assertEquals(product.getId(), fetchedProduct.getId());
assertEquals(product.getDescription(), fetchedProduct.getDescription());
//update description and save
fetchedProduct.setDescription("New Description");
productRepository.save(fetchedProduct);
//get from DB, should be updated
Product fetchedUpdatedProduct = productRepository
.findOne(fetchedProduct.getId());
assertEquals(fetchedProduct.getDescription(),
fetchedUpdatedProduct.getDescription());
//verify count of products in DB
long productCount = productRepository.count();
assertEquals(productCount, 1);
//get all products, list should only have one
Iterable<Product> products = productRepository.findAll();
int count = 0;
for(Product p : products){
count++;
}
assertEquals(count, 1);
}
}Activating Logging in Hibernate
To activate the logging of the executed SQL statements with Spring Boot, set the log level of the org.hibernate.SQL category to DEBUG.
If you wish to see the bind values, you can set the log level of org.hibernate.type.descriptor.sql to TRACE.
If you are new to logging frameworks, refer my series on Log4J2.
Here is the logging configuration in the application.properties.
application.properties:
#show sql statement
logging.level.org.hibernate.SQL=debug
#show sql values
logging.level.org.hibernate.type.descriptor.sql=traceHere is the log output showing the SQL statements generated by Hibernate:
org.hibernate.SQL=debug
2018-02-04 22:34:46.861 DEBUG 1065 --- [ main] org.hibernate.SQL :
select product0_.id as id1_0_0_, product0_.description as descript2_0_0_, product0_.image_url as image_ur3_0_0_, product0_.price as price4_0_0_, product0_.product_id as product_5_0_0_, product0_.version as version6_0_0_ from product product0_ where product0_.id=?
org.hibernate.type.descriptor.sql=trace
2018-02-04 22:34:46.861 DEBUG 1065 --- [ main] org.hibernate.SQL :
select product0_.id as id1_0_0_, product0_.description as descript2_0_0_, product0_.image_url as image_ur3_0_0_, product0_.price as price4_0_0_, product0_.product_id as product_5_0_0_, product0_.version as version6_0_0_ from product product0_ where product0_.id=?
2018-02-04 22:34:46.862 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicBinder :
binding parameter [1] as [INTEGER] - [1]
2018-02-04 22:34:46.862 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicExtractor :
extracted value ([descript2_0_0_] : [VARCHAR]) - [New Description]
2018-02-04 22:34:46.863 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicExtractor :
extracted value ([image_ur3_0_0_] : [VARCHAR]) - [https://springframework.guru/wp-content/uploads/2015/04/spring_framework_guru_shirt-rf412049699c14ba5b68bb1c09182bfa2_8nax2_512.jpg]
2018-02-04 22:34:46.863 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([price4_0_0_] : [NUMERIC]) - [18.95]
2018-02-04 22:34:46.863 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([product_5_0_0_] : [VARCHAR]) - [1234]
2018-02-04 22:34:46.863 TRACE 1065 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([version6_0_0_] : [INTEGER]) - [1]Activating Logging With Spring Data JPA
If you are using Spring Data JPA with Hibernate as the persistence provider, add the following two lines in application.properties:
spring.jpa.show-sql=true
spring.jpa.properties.hibernate.format_sql=trueHere is the log output:
Hibernate:
select
product0_.id as id1_0_0_,
product0_.description as descript2_0_0_,
product0_.image_url as image_ur3_0_0_,
product0_.price as price4_0_0_,
product0_.product_id as product_5_0_0_,
product0_.version as version6_0_0_
from
product product0_
where
product0_.id=?Conclusion
As you can see, it's very easy to enable the logging of SQL statements with Spring Boot and Hibernate.
Being able to see what Hibernate is actually doing with the database is very important.
Often, when I'm working on a Spring Boot project, I will enable the SQL output just as a sanity check. I may believe everything is okay. But I have, in fact, found problems which I was unaware of by examining the SQL output.
