How To Find Origin And Context of JPA For Issued SQL Statements

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 / / etc. on the domain classes and 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. @Entity @ManyToOne @OneToMany EntityManager 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 i.e. due to problem excessive lady-loading N+1 SELECT Eager fetches performed (i.e fetchType = on associations) in inefficient way FetchType.EAGER No easy way to invoked across some use case / service call and to list all SQL statements 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 how these problems could be detected, but first let’s see to classic way. new approach 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 property. spring.jpa.show-sql As a result a log like the one below can be reported: 2020-10-31 19:37:40.730 DEBUG 15775 products0_.order_id order_id1_9_0_, products0_.product_id product_2_9_0_, product1_.id id1_14_1_, product1_.manufacturer_id manufact3_14_1_, product1_.name name2_14_1_ order_product products0_ product product1_ products0_.product_id=product1_.id products0_.order_id=? --- [ main] org.hibernate.SQL : select as as as as as from inner join on where 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 book (author_id, title, ) (?, ?, ?) --- [ main] org.hibernate.SQL : /* insert com.adgadev.blog.examples.bookshop.Book */ insert into id values In general such logs can be useful, but they lack one crucial information: . 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? How to locate place in application source code responsible for triggering it 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 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. JPlusOne 2020-11-26 22:20:52.096 DEBUG 9990 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] [...] book book0_ book0_.id= OPERATION [IMPLICIT] com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java: ) com.adgadev.examples.bookshop.Author.getName [PROXY] com.adgadev.examples.bookshop.Author [FETCHING ENTITY] [ ] [...] author author0_ author0_.id= OPERATION [IMPLICIT] com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java: ) com.adgadev.examples.bookshop.Author.countWrittenBooks(Author.java: ) com.adgadev.examples.bookshop.Author.books [FETCHING COLLECTION] [ ] [...] book books0_ books0_.author_id= --- [ main] c.a.j.core.report.ReportGenerator : select from where 1 34 STATEMENT READ select from where 1 35 41 STATEMENT READ select from where 1 Moreover, it detects what kind of action triggered it: implicit fetching single entity to initialize lazy-loaded "one" side of the association ( / with set to ) @ManyToOne @OneToOne fetch LAZY implicit fetching collection of entities to initialize lazy-loaded "many" side of the association ( / with set to ) @OneToMany @ManyToMany fetch LAZY explicit fetching of data via repository call (SpringData JPA, custom DAO) or directly via EntityManager / triggered at the transaction commit INSERT SELECT is compatible with all Spring Boot 2.x based application running on JDK 9+ with Hibernate as JPA implementor. JPlusOne Sample JPA domain & service To better illustrate the examples let’s assume we have simple domain consisting of two JPA entities. First one is entity: Author { Long id; String name; (fetch = FetchType.LAZY, mappedBy = ) Set books = HashSet<>(); { books.size(); } } @Getter @Entity class Author @Id private private @OneToMany "author" private new int countWrittenBooks () return and second one is entity: Book (of = ) { Long id; String title; (fetch = FetchType.LAZY) (name = ) Author author; } @Getter @Entity @EqualsAndHashCode "id" class Book @Id private private @ManyToOne @JoinColumn "author_id" private There is also a simple service : BookshopService { BookRepository bookRepository; { Book book = bookRepository.findById( ).get(); String authorName = book.getAuthor().getName(); amountOfBooks = book.getAuthor().countWrittenBooks(); BookDto(authorName, book.getTitle(), amountOfBooks); } } @Service @Transactional @RequiredArgsConstructor class BookshopService private final BookDto public getSampleBookDetails () 1L int return new and a simple MVC controller: { BookshopService bookshopService; ( ) { bookshopService.getSampleBookDetails(); } } @RestController @RequiredArgsConstructor class BookshopController private final @GetMapping "/book/lazy" BookDto getSampleBook () return Reporting JPA lazy-loading operations and related SQL statements In order to detect JPA lazy loading operations let’s add following dependency: com.adgadev.jplusone jplusone-core 1.0.1 test dependency groupId groupId artifactId artifactId version version scope 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 endpoint. BookshopController ( ) (webEnvironment = MOCK) { MockMvc mvc; { mvc.perform(MockMvcRequestBuilders .get( ) .accept(MediaType.APPLICATION_JSON)) .andExpect(status().isOk()); } } @ActiveProfiles "integration-test" @SpringBootTest @AutoConfigureMockMvc class BookshopControllerTest @Autowired private @Test Exception void shouldGetBookDetails () throws "/book/lazy" 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 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] [...] author author0_ author0_.id= OPERATION [IMPLICIT] com.adgadev.examples.bookshop.BookshopService.getSampleBookDetails(BookshopService.java: ) com.adgadev.examples.bookshop.Author.countWrittenBooks(Author.java: ) com.adgadev.examples.bookshop.Author.books [FETCHING COLLECTION] [ ] [...] book books0_ books0_.author_id= --- [ main] c.a.j.core.report.ReportGenerator : select from where 1 35 41 STATEMENT READ select from where 1 In this case we see that there was two lazy loading operations: Within method there was execution of method on object which was proxy to JPA entity . As a result initialisation of this proxy object was triggered, causing execution of SQL query. BookshopService.getSampleBookDetailsUsingLazyLoading getName Author Within method a content of collection representing "many" side of the association with entities has been accessed. As a result initialisation of this collection was triggered ( ) along with execution of SQL query. Author.countWrittenBooks books Book Author.books 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 ( ) resulting in SQL statements are included in a report. JPA operations related with explicit calls to fetch / flush some data ( ) are not included. Likewise, operations related with session flush on transaction commit ( ). IMPLICIT SELECT EXPLICIT COMMIT Default behaviour can be easily changed by defining custom filtering criteria by adding following lines to More details about supported filtering modes and other configuration options can be found in . application.yml 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 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] [...] book book0_ book0_.id= --- [ main] c.a.j.core.report.ReportGenerator : select from where 1 Report shows that there is one explicit fetch operation, triggered in in line 34 by calling method of Spring Data JPA repository , which result in one SQL query being executed. BookshopService.getSampleBookDetailsUsingLazyLoading findById BookRepository 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 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. ArchUnit Let’s extend integration test from previous example with validation checking that there are only two JPA lazy loading operations: first for loading JPA entity, and second for loading collection. In order to write such tests following dependency needs to be added: Author Author.books com.adgadev.jplusone jplusone-assert 1.0.1 test dependency groupId groupId artifactId artifactId version version scope scope dependency and then object has to be defined and checked against injected . JPlusOneAssertionRule assertionContext ( ) (webEnvironment = MOCK) { JPlusOneAssertionContext assertionContext; MockMvc mvc; { mvc.perform(MockMvcRequestBuilders .get( ) .accept(MediaType.APPLICATION_JSON)) .andExpect(status().isOk()); JPlusOneAssertionRule rule = JPlusOneAssertionRule .within().lastSession() .shouldBe().noImplicitOperations().exceptAnyOf(exclusions -> exclusions .loadingEntity(Author.class) .loadingCollection(Author.class, ) ); rule.check(assertionContext); } } @ActiveProfiles "integration-test" @SpringBootTest @AutoConfigureMockMvc class BookshopControllerTest @Autowired private @Autowired private @Test Exception void shouldGetBookDetails () throws "/book/lazy" "books" 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 from: BookshopService.getSampleBookDetailsUsingLazyLoading Book book = bookRepository.findById( ).get(); 1L 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 entity. When test is re-run is thrown: Book AssertionError java.lang.AssertionError: Actual amount of IMPLICIT operations after applying exclusions is different than the expected amount Expected: exactly (0) Actual : (1) 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] [...] book book0_ book0_.id= com.adgadev.jplusone.asserts.impl.rule.AmountVerifier.checkAmount(AmountVerifier.java: ) com.adgadev.jplusone.asserts.impl.rule.Condition.checkOperation(Condition.java: ) com.adgadev.jplusone.asserts.impl.rule.Condition.check(Condition.java: ) com.adgadev.jplusone.asserts.impl.rule.Rule.lambda$ $ (Rule.java: ) java.base/java.util.ArrayList.forEach(ArrayList.java: ) com.adgadev.jplusone.asserts.impl.rule.Rule.check(Rule.java: ) com.adgadev.jplusone.asserts.impl.Assertion.check(Assertion.java: ) com.adgadev.jplusone.asserts.impl.ConditionDoneBuilderImpl.check(ConditionDoneBuilderImpl.java: ) com.adgadev.examples.bookshop.BookshopControllerTest.shouldGetBookDetails(BookshopControllerTest.java: ) ... select from where 1 at 44 at 84 at 54 at check 0 48 at 1540 at 48 at 38 at 38 at 57 Summary The full source code of the examples is available . here If you find useful and worth further development, please star the project repository on , thanks! JPlusOne library GitHub Previously published at https://adgadev.com/finding-origin-and-context-of-jpa-issued-sql-statemets/