Finding origin and context of JPA issued SQL statements
Tags: java, showdev, performance, jpa
Published: 2020-12-03 10:42:19



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.EAGER` on 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`
```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:
```sql
    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:
```sql
    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](https://github.com/adgadev/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.
```sql
    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` / `@OneToOne` with `fetch` set to `LAZY`)

-   implicit fetching collection of entities to initialize lazy-loaded "many" side of the association (`@OneToMany` / `@ManyToMany` with `fetch` set to `LAZY`)

-   explicit fetching of data via repository call (SpringData JPA, custom DAO) or directly via `EntityManager`

-   `INSERT` / `SELECT` triggered at the transaction commit

[JPlusOne](https://github.com/adgadev/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:
```java
    @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:
```java
    @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`:
```java
    @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:
```java
    @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:
```xml
    <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`:
```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.
```java
    @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:
```sql
    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.getSampleBookDetailsUsingLazyLoading` there was execution of method `getName` on object which was proxy to JPA entity `Author`. As a result initialisation of this proxy object was triggered, causing execution of SQL query.

-   Within method `Author.countWrittenBooks` a content of collection `books` representing "many" side of the association with `Book` entities 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](https://github.com/adgadev/jplusone#configuration-properties).
```yml
    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:
```sql
    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](https://www.archunit.org/) 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:
```xml
    <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`.
```java
    @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:
```java
            Book book = bookRepository.findById(1L).get();
```
to:
```java
            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](https://github.com/adgadev/blog-examples/tree/master/jplusone-in-action).

If you find [JPlusOne library](https://github.com/adgadev/jplusone) useful and worth further development, please star the project repository on [GitHub](https://github.com/adgadev/jplusone), thanks!