Finding origin and context of JPA issued SQL statements-Adam Gaj Blog

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

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 / @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 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.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.

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 (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]
                            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!

Finding origin and context of JPA issued SQL statements

Automatic correlating executed SQL statements with exact places in code responsible for triggering them and with detailed use case context, in JPA based applications using JPlusOne library

TOC