DEV Community

Adam Gaj
Adam Gaj

Posted on • Updated on • Originally published at adgadev.com

Finding origin and context of JPA issued SQL statements

#java #showdev #performance #jpa

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
Enter fullscreen mode Exit fullscreen mode

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=?
Enter fullscreen mode Exit fullscreen mode

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
                (?, ?, ?)
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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();
        }
    }
Enter fullscreen mode Exit fullscreen mode

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;

    }
Enter fullscreen mode Exit fullscreen mode

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);
        }
    }
Enter fullscreen mode Exit fullscreen mode

and a simple MVC controller:

    @RestController
    @RequiredArgsConstructor
    class BookshopController {

        private final BookshopService bookshopService;

        @GetMapping("/book/lazy")
        BookDto getSampleBook() {
            return bookshopService.getSampleBookDetails();
        }
    }
Enter fullscreen mode Exit fullscreen mode

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>
Enter fullscreen mode Exit fullscreen mode

The last step is to configure logger for jplusone, i.e. by adding following lines to application.yml:

    logging.level:
        com.adgadev.jplusone: DEBUG
Enter fullscreen mode Exit fullscreen mode

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());
        }
    }
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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
Enter fullscreen mode Exit fullscreen mode

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>
Enter fullscreen mode Exit fullscreen mode

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);
        }
    }
Enter fullscreen mode Exit fullscreen mode

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();
Enter fullscreen mode Exit fullscreen mode

to:

            Book book = bookRepository.getOne(1L);
Enter fullscreen mode Exit fullscreen mode

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)
        ...
Enter fullscreen mode Exit fullscreen mode

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!

Top comments (0)

Read next

dominik_gawlik_431ca4cb96 profile image

Writing k8s operator in Java

Dominik Gawlik -

sunnyss profile image

Java Programming

sunny -

birkssachdev profile image

Automate Your Java Tasks with Quartz: A Practical Guide

Birks Sachdev -

datkumar profile image

The preferred way to install and manage Java JDKs on Linux

Kumar Deshmukh -