Finding origin and context of JPA issued SQL statements
What problem are we solving here?
ORM frameworks like Hibernate and other JPA implementors can significantly simplify development of persistence layer. Introducing entity abstraction level helps to model clean business domain and to hide underlying SQL statements used to achieve persistence of the domain. Such approach is especially useful in large domains, since developer no longer needs to create and maintain all SQL statements used by application. Just a few JPA annotations like @Entity / @ManyToOne / @OneToMany etc. on the domain classes and EntityManager or custom repositories to obtain domain aggregate roots, and you are ready to go. Having that, the vast majority of use cases involving persistence can be handled in domain model by JPA cascades and traversing associations and performing operations on them.
Everything comes with a price. In exchange for clean and easy development, some issues can arise sooner or later:
Large amount of SQL statements issued by excessive lady-loading i.e. due to N+1 SELECT problem
Eager fetches performed in inefficient way (i.e
fetchType = FetchType.EAGERon associations)No easy way to list all SQL statements invoked across some use case / service call and to correlate them with exact lines of code
Even if for some use case fetching had been optimized to load all necessary data in efficient way, future change in code can silently break it, and there is no way easy to prevent it.
In next steps I’ll show the new approach how these problems could be detected, but first let’s see to classic way.
Logging JPA issued SQL statements by Hibernate
As for now the easiest way to check what SQL statements were executed by JPA was to enable logging of all SQL statements issued by JPA, and then investigate one by one if it was triggered by lazy loading or explicit repository call to fetch/flush some data or maybe commit of transaction triggered it. To enable logging SQL statements executed by JPA via logger, following properties needs to be added in application.yml
logging.level:
org.hibernate.SQL: DEBUG
spring:
jpa:
properties:
hibernate:
format_sql: true # optional
use_sql_comments: true # optional
Logging to stdout (legacy) instead of via logger can be activated by enabling spring.jpa.show-sql property.
As a result a log like the one below can be reported:
2020-10-31 19:37:40.730 DEBUG 15775 --- [ main] org.hibernate.SQL :
select
products0_.order_id as order_id1_9_0_,
products0_.product_id as product_2_9_0_,
product1_.id as id1_14_1_,
product1_.manufacturer_id as manufact3_14_1_,
product1_.name as name2_14_1_
from
order_product products0_
inner join
product product1_
on products0_.product_id=product1_.id
where
products0_.order_id=?
Part of the hibernate logs may contain SQL comments associating SQL statement with the JPA entity class:
2020-11-25 23:51:58.390 DEBUG 28750 --- [ main] org.hibernate.SQL :
/* insert com.adgadev.blog.examples.bookshop.Book */ insert
into
book
(author_id, title, id)
values
(?, ?, ?)
In general such logs can be useful, but they lack one crucial information: How to locate place in application source code responsible for triggering it. Was it executed as a result of initializing entity’s proxy while traversing though JPA entity associations or maybe it was a result of explicit JPQL query execution by a service? If multiple various services in the application could have triggered such query which one of them was it? What was the flow?
You can try to guess it when the domain and the logic in your codebase is simple or SQL statement points to just one specific place in the code, but it’s not always that easy, especially with queries generated by JPA to lazy load some entities. In such case debugging the code and checking which exact line causes SQL statement may be the only option. Another problem with debugging is that it can alter the real flow how entities are loaded due to resolving variables' values at breakpoint by IDE. Now imagine situation when invoking a service causes dozens of SQL being triggered from various places in your code called by such service. Investigating it is cumbersome and can really take a lot of time.
JPlusOne comes to the rescue
JPlusOne library aims to solve these problems. It can generate concise reports with all JPA/SQL activity triggered during handling some use cases by your application. That way you can easily correlate invoked SQL statements with JPA operations and locate exact lines in the code responsible for issuing them.
2020-11-26 22:20:52.096 DEBUG 9990 --- [ main] c.a.j.core.report.ReportGenerator :
ROOT
com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java:46)
com.adgadev.examples.bookshop.BookshopController.getSampleBook(BookshopController.java:31)
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails [PROXY]
SESSION BOUNDARY
OPERATION [EXPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:32)
com.adgadev.examples.bookshop.BookRepository.findById [PROXY]
STATEMENT [READ]
select [...] from
book book0_
where
book0_.id=1
OPERATION [IMPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:34)
com.adgadev.examples.bookshop.Author.getName [PROXY]
com.adgadev.examples.bookshop.Author [FETCHING ENTITY]
STATEMENT [READ]
select [...] from
author author0_
where
author0_.id=1
OPERATION [IMPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:35)
com.adgadev.examples.bookshop.Author.countWrittenBooks(Author.java:41)
com.adgadev.examples.bookshop.Author.books [FETCHING COLLECTION]
STATEMENT [READ]
select [...] from
book books0_
where
books0_.author_id=1
Moreover, it detects what kind of action triggered it:
implicit fetching single entity to initialize lazy-loaded "one" side of the association (
@ManyToOne/@OneToOnewithfetchset toLAZY)implicit fetching collection of entities to initialize lazy-loaded "many" side of the association (
@OneToMany/@ManyToManywithfetchset toLAZY)explicit fetching of data via repository call (SpringData JPA, custom DAO) or directly via
EntityManagerINSERT/SELECTtriggered at the transaction commit
JPlusOne is compatible with all Spring Boot 2.x based application running on JDK 9+ with Hibernate as JPA implementor.
Sample JPA domain & service
To better illustrate the examples let’s assume we have simple domain consisting of two JPA entities. First one is Author entity:
@Getter
@Entity
class Author {
@Id
private Long id;
private String name;
@OneToMany(fetch = FetchType.LAZY, mappedBy = "author")
private Set<Book> books = new HashSet<>();
int countWrittenBooks() {
return books.size();
}
}
and second one is Book entity:
@Getter
@Entity
@EqualsAndHashCode(of = "id")
class Book {
@Id
private Long id;
private String title;
@ManyToOne(fetch = FetchType.LAZY)
@JoinColumn(name = "author_id")
private Author author;
}
There is also a simple service BookshopService:
@Service
@Transactional
@RequiredArgsConstructor
class BookshopService {
private final BookRepository bookRepository;
public BookDto getSampleBookDetails() {
Book book = bookRepository.findById(1L).get();
String authorName = book.getAuthor().getName();
int amountOfBooks = book.getAuthor().countWrittenBooks();
return new BookDto(authorName, book.getTitle(), amountOfBooks);
}
}
and a simple MVC controller:
@RestController
@RequiredArgsConstructor
class BookshopController {
private final BookshopService bookshopService;
@GetMapping("/book/lazy")
BookDto getSampleBook() {
return bookshopService.getSampleBookDetails();
}
}
Reporting JPA lazy-loading operations and related SQL statements
In order to detect JPA lazy loading operations let’s add following dependency:
<dependency>
<groupId>com.adgadev.jplusone</groupId>
<artifactId>jplusone-core</artifactId>
<version>1.0.1</version>
<scope>test</scope>
</dependency>
The last step is to configure logger for jplusone, i.e. by adding following lines to application.yml:
logging.level:
com.adgadev.jplusone: DEBUG
Spring Boot’a autoconfiguration will do the rest of configuration automatically. Now let’s run any integration test, which directly or indirectly utilizes JPA persistence, i.e. the test which sends request to BookshopController endpoint.
@ActiveProfiles("integration-test")
@SpringBootTest(webEnvironment = MOCK)
@AutoConfigureMockMvc
class BookshopControllerTest {
@Autowired
private MockMvc mvc;
@Test
void shouldGetBookDetails() throws Exception {
mvc.perform(MockMvcRequestBuilders
.get("/book/lazy")
.accept(MediaType.APPLICATION_JSON))
.andExpect(status().isOk());
}
}
It will result in adding a log entry containing JPlusOne report of JPA operations / SQL statements, like the one below:
2020-11-26 22:27:59.683 DEBUG 10730 --- [ main] c.a.j.core.report.ReportGenerator :
ROOT
com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java:46)
com.adgadev.examples.bookshop.BookshopController.getSampleBook(BookshopController.java:31)
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails [PROXY]
SESSION BOUNDARY
OPERATION [IMPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:34)
com.adgadev.examples.bookshop.Author.getName [PROXY]
com.adgadev.examples.bookshop.Author [FETCHING ENTITY]
STATEMENT [READ]
select [...] from
author author0_
where
author0_.id=1
OPERATION [IMPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:35)
com.adgadev.examples.bookshop.Author.countWrittenBooks(Author.java:41)
com.adgadev.examples.bookshop.Author.books [FETCHING COLLECTION]
STATEMENT [READ]
select [...] from
book books0_
where
books0_.author_id=1
In this case we see that there was two lazy loading operations:
Within method
BookshopService.getSampleBookDetailsUsingLazyLoadingthere was execution of methodgetNameon object which was proxy to JPA entityAuthor. As a result initialisation of this proxy object was triggered, causing execution of SQL query.Within method
Author.countWrittenBooksa content of collectionbooksrepresenting "many" side of the association withBookentities has been accessed. As a result initialisation of this collection was triggered (Author.books) along with execution of SQL query.
Due to the fact that queries generated by JPA, especially those where a few joins are applied, can contain very large number of selected columns, which doesn’t bring too much value from performance optimisation point of view but degrade readability of complex SQL statements, JPlusOne replaces them with […] in a report.
Reporting other types of JPA operations and related SQL statements
By default only lazy loading operations (IMPLICIT) resulting in SQL SELECT statements are included in a report. JPA operations related with explicit calls to fetch / flush some data (EXPLICIT) are not included. Likewise, operations related with session flush on transaction commit (COMMIT).
Default behaviour can be easily changed by defining custom filtering criteria by adding following lines to application.yml More details about supported filtering modes and other configuration options can be found in JPlusOne documentation.
jplusone:
report:
operation-filtering-mode: EXPLICIT_OPERATIONS_ONLY
statement-filtering-mode: ALL_STATEMENTS
Running the same test as in previous example result now in following report:
2020-11-26 22:30:13.497 DEBUG 10997 --- [ main] c.a.j.core.report.ReportGenerator :
ROOT
com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java:46)
com.adgadev.examples.bookshop.BookshopController.getSampleBook(BookshopController.java:31)
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails [PROXY]
SESSION BOUNDARY
OPERATION [EXPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:32)
com.adgadev.examples.bookshop.BookRepository.findById [PROXY]
STATEMENT [READ]
select [...] from
book book0_
where
book0_.id=1
Report shows that there is one explicit fetch operation, triggered in BookshopService.getSampleBookDetailsUsingLazyLoading in line 34 by calling method findById of Spring Data JPA repository BookRepository, which result in one SQL query being executed.
Ensuring JPA / SQL optimized service stays optimized in future
Nowadays tests no longer serves just purpose of ensuring that a piece of code works as expected and is bug free. Other aspects of the code also can be tested. Great example of it is a ArchUnit which allows unit testing architecture of the application, i.e. ensuring layered structure of the application is maintained. Since you can unit test architecture, why not test if once optimized from JPA/SQL performance point of view use case logic stays optimized after future changes in the code? Adding or modifying some JPA mapping / association can easily introduce some additional lazy loading operation in some flows, but it may be hard to spot that when such change is applied.
Let’s extend integration test from previous example with validation checking that there are only two JPA lazy loading operations: first for loading Author JPA entity, and second for loading Author.books collection. In order to write such tests following dependency needs to be added:
<dependency>
<groupId>com.adgadev.jplusone</groupId>
<artifactId>jplusone-assert</artifactId>
<version>1.0.1</version>
<scope>test</scope>
</dependency>
and then JPlusOneAssertionRule object has to be defined and checked against injected assertionContext.
@ActiveProfiles("integration-test")
@SpringBootTest(webEnvironment = MOCK)
@AutoConfigureMockMvc
class BookshopControllerTest {
@Autowired
private JPlusOneAssertionContext assertionContext;
@Autowired
private MockMvc mvc;
@Test
void shouldGetBookDetails() throws Exception {
mvc.perform(MockMvcRequestBuilders
.get("/book/lazy")
.accept(MediaType.APPLICATION_JSON))
.andExpect(status().isOk());
JPlusOneAssertionRule rule = JPlusOneAssertionRule
.within().lastSession()
.shouldBe().noImplicitOperations().exceptAnyOf(exclusions -> exclusions
.loadingEntity(Author.class)
.loadingCollection(Author.class, "books")
);
rule.check(assertionContext);
}
}
Since the rule is fulfilled the test is green. Let’s see what happens when third lazy loading operation is introduced to implementation. The easiest way to do that would be to change single line in BookshopService.getSampleBookDetailsUsingLazyLoading from:
Book book = bookRepository.findById(1L).get();
to:
Book book = bookRepository.getOne(1L);
causing JPA proxy being returned instead of JPA entity. The proxy will be initialized on first operation invoked on it, leading to lazy-loading of Book entity. When test is re-run AssertionError is thrown:
java.lang.AssertionError: Actual amount of IMPLICIT operations after applying exclusions is different than the expected amount
Expected: exactly
Actual :
Operations after applying requested exclusions:
ROOT
com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java:46)
com.adgadev.examples.bookshop.BookshopController.getSampleBook(BookshopController.java:31)
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails [PROXY]
SESSION BOUNDARY
OPERATION [IMPLICIT]
com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java:34)
com.adgadev.examples.bookshop.Book.getAuthor [PROXY]
com.adgadev.examples.bookshop.Book [FETCHING ENTITY]
STATEMENT [READ]
select [...] from
book book0_
where
book0_.id=1
at com.adgadev.jplusone.asserts.impl.rule.AmountVerifier.checkAmount(AmountVerifier.java:44)
at com.adgadev.jplusone.asserts.impl.rule.Condition.checkOperation(Condition.java:84)
at com.adgadev.jplusone.asserts.impl.rule.Condition.check(Condition.java:54)
at com.adgadev.jplusone.asserts.impl.rule.Rule.lambda$check$0(Rule.java:48)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1540)
at com.adgadev.jplusone.asserts.impl.rule.Rule.check(Rule.java:48)
at com.adgadev.jplusone.asserts.impl.Assertion.check(Assertion.java:38)
at com.adgadev.jplusone.asserts.impl.ConditionDoneBuilderImpl.check(ConditionDoneBuilderImpl.java:38)
at com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java:57)
...
Summary
The full source code of the examples is available here.
If you find JPlusOne library useful and worth further development, please star the project repository on GitHub, thanks!
