Merge pull request #9 from yannbriancon/bug-fix-false-positive-findById-queries

Bug fix false positive find by id queries

Author: yannbriancon

README.md

@@ -41,7 +41,7 @@
   * [Prerequisites](#prerequisites)
   * [Installation](#installation)
 * [Usage](#usage)
-  * [N+1 Query Detection](#n1-query-detection)
+  * [N+1 Queries Detection](#n1-queries-detection)
     * [Detection](#detection)
     * [Configuration](#configuration)
   * [Query Count](#query-count)
@@ -53,7 +53,9 @@
 <!-- ABOUT THE PROJECT -->
 ## About The Project
 
-While investigating the performance problems in my SpringBoot application, I discovered the infamous N+1 queries problem (more details on this problem [here](https://medium.com/@mansoor_ali/hibernate-n-1-queries-problem-8a926b69f618)) that was killing the performance of my services.
+While investigating the performance problems in my SpringBoot application, I discovered the infamous N+1 queries 
+problem that was killing the performance of my services. 
+Check the article [Eliminate Spring Hibernate N+1 Queries](https://medium.com/sipios/eliminate-spring-hibernate-n-plus-1-queries-f0bcf6a83de2?source=friends_link&sk=5ba0f2493af1d8496a46d5f116effa96) for more details.
 
 After managing to fix this problem, I had to find a way to detect it and raise the alarm to avoid any developer to introduce new ones.
 
@@ -84,29 +86,29 @@ Add the dependency to your project inside your `pom.xml` file
 <dependency>
     <groupId>com.yannbriancon</groupId>
     <artifactId>spring-hibernate-query-utils</artifactId>
-    <version>1.0.1</version>
+    <version>1.0.2</version>
 </dependency>
 ```
 
 
 <!-- USAGE -->
 ## Usage
 
-### N+1 Query Detection
+### N+1 Queries Detection
 
 #### Detection
 
-The N+1 query detection is enabled by default so no configuration is needed.
+The N+1 queries detection is enabled by default so no configuration is needed.
 
-Each time a N+1 query is detected in a transaction, a log of level error will be sent.
+Each time N+1 queries are detected in a transaction, a log of level error will be sent.
 
-Here is an example catching the error log:
+Here is an example catching the N+1 queries detection error log:
 
 ```java
 @RunWith(MockitoJUnitRunner.class)
 @SpringBootTest
 @Transactional
-class NPlusOneQueryLoggingTest {
+class NPlusOneQueriesLoggingTest {
 
     @Autowired
     private MessageRepository messageRepository;
@@ -124,42 +126,47 @@ class NPlusOneQueryLoggingTest {
     }
 
     @Test
-    void nPlusOneQueryDetection_isLoggingWhenDetectingNPlusOneQuery() {
+    void nPlusOneQueriesDetection_isLoggingWhenDetectingNPlusOneQueries() {
         // Fetch the 2 messages without the authors
         List<Message> messages = messageRepository.findAll();
-    
-        // Trigger N+1 query
+
+        // The getters trigger N+1 queries
         List<String> names = messages.stream()
                 .map(message -> message.getAuthor().getName())
                 .collect(Collectors.toList());
-    
+
         verify(mockedAppender, times(2)).doAppend(loggingEventCaptor.capture());
-    
+
         LoggingEvent loggingEvent = loggingEventCaptor.getAllValues().get(0);
-        assertThat("N+1 query detected for entity: com.yannbriancon.utils.entity.User")
-                .isEqualTo(loggingEvent.getMessage());
+        assertThat(loggingEvent.getMessage())
+                .isEqualTo("N+1 queries detected on a getter of the entity com.yannbriancon.utils.entity.User\n" +
+                        "    at com.yannbriancon.interceptor.NPlusOneQueriesLoggingTest." +
+                        "lambda$nPlusOneQueriesDetection_isLoggingWhenDetectingNPlusOneQueries$0" +
+                        "(NPlusOneQueriesLoggingTest.java:56)\n" +
+                        "    Hint: Missing Eager fetching configuration on the query that fetches the object of type" +
+                        " com.yannbriancon.utils.entity.User\n");
         assertThat(Level.ERROR).isEqualTo(loggingEvent.getLevel());
     }
 }
 ```
 
 #### Configuration
 
-By default the detection of a N+1 query logs an error to avoid breaking your code. 
+By default the detection of N+1 queries logs an error to avoid breaking your code. 
 
-However, my advise is to override the default error level to throw exceptions for your test profile. 
+However, my advice is to override the default error level to throw exceptions for your test profile. 
 
 Now you will easily detect which tests are failing and be able to flag them and set the error level to error logs only on 
 those tests while you are fixing them.
 
-To do this, you can configure the error level when a N+1 query is detected using the property `hibernate.query.interceptor.error-level`. 
+To do this, you can configure the error level when N+1 queries is detected using the property `hibernate.query.interceptor.error-level`. 
 
 4 levels are available to handle the detection of N+1 queries:
 
 * **INFO**: Log a message of level info
 * **WARN**: Log a message of level warn
 * **ERROR** (default): Log a message of level error
-* **EXCEPTION**: Throw a NPlusOneQueryException
+* **EXCEPTION**: Throw a NPlusOneQueriesException
 
 Here are two examples on how to use it globally or for a specific test:
 
@@ -172,7 +179,7 @@ hibernate.query.interceptor.error-level=INFO
 ```java
 @SpringBootTest("hibernate.query.interceptor.error-level=INFO")
 @Transactional
-class NPlusOneQueryLoggingTest {
+class NPlusOneQueriesLoggingTest {
     ...
 }
 ```
@@ -202,7 +209,7 @@ public class NotificationResourceIntTest {
     private HibernateQueryInterceptor hibernateQueryInterceptor;
 
     @Test
-    public void saveFile_isOk() throws Exception {
+    public void getNotification_isOk() throws Exception {
         // Initialize the query to 0 and allow the counting
         hibernateQueryInterceptor.startQueryCount();
 
@@ -211,8 +218,8 @@ public class NotificationResourceIntTest {
                 .andExpect(status().isOk())
                 .andReturn();
 
-        // Get the query count for this thread and check that it is equal to the number of query you expect, let's say 4.
-        // The count is checked and we detect potential n+1 queries.
+        // Get the query count for this thread and check that it is equal to the number of query you expect,
+        // Let's say 4 for the example.
         Assertions.assertThat(hibernateQueryInterceptor.getQueryCount()).isEqualTo(4);
     }
 }

pom.xml

@@ -5,7 +5,7 @@
 
     <groupId>com.yannbriancon</groupId>
     <artifactId>spring-hibernate-query-utils</artifactId>
-    <version>1.0.1</version>
+    <version>1.0.2</version>
     <packaging>jar</packaging>
 
     <name>spring-hibernate-query-utils</name>

src/main/java/com/yannbriancon/exception/NPlusOneQueriesException.java

@@ -0,0 +1,16 @@
+package com.yannbriancon.exception;
+
+import org.hibernate.CallbackException;
+
+/**
+ * Exception triggered when detecting N+1 queries
+ */
+public class NPlusOneQueriesException extends CallbackException {
+    public NPlusOneQueriesException(String message, Exception cause) {
+        super(message, cause);
+    }
+
+    public NPlusOneQueriesException(String message) {
+        super(message);
+    }
+}

src/main/java/com/yannbriancon/exception/NPlusOneQueryException.java

@@ -1,6 +1,6 @@
 package com.yannbriancon.interceptor;
 
-import com.yannbriancon.exception.NPlusOneQueryException;
+import com.yannbriancon.exception.NPlusOneQueriesException;
 import org.hibernate.EmptyInterceptor;
 import org.hibernate.Transaction;
 import org.hibernate.proxy.HibernateProxy;
@@ -11,6 +11,7 @@
 
 import java.io.Serializable;
 import java.util.HashSet;
+import java.util.Optional;
 import java.util.Set;
 import java.util.function.Supplier;
 
@@ -62,7 +63,7 @@ public String onPrepareStatement(String sql) {
 
     /**
      * Reset previously loaded entities after the end of a transaction to avoid triggering
-     * N+1 query exceptions because of loading same instance in two different transactions
+     * N+1 queries exceptions because of loading same instance in two different transactions
      *
      * @param tx Transaction having been completed
      */
@@ -87,7 +88,8 @@ public Object getEntity(String entityName, Serializable id) {
         if (previouslyLoadedEntities.contains(entityName + id)) {
             previouslyLoadedEntities.remove(entityName + id);
             threadPreviouslyLoadedEntities.set(previouslyLoadedEntities);
-            logDetectedNPlusOneQuery(entityName);
+            Optional<String> errorMessage = detectNPlusOneQueries(entityName);
+            errorMessage.ifPresent(this::logDetectedNPlusOneQueries);
         }
 
         previouslyLoadedEntities.add(entityName + id);
@@ -97,12 +99,35 @@ public Object getEntity(String entityName, Serializable id) {
     }
 
     /**
-     * Log the detected N+1 query or throw an exception depending on the configured error level
+     * Detect the N+1 queries by checking if the stack trace contains an Hibernate Proxy on the Entity
      *
-     * @param entityName Name of the entity on which the N+1 query has been detected
+     * @param entityName Name of the entity
+     * @return If N+1 queries detected, return error message corresponding to the N+1 queries
      */
-    private void logDetectedNPlusOneQuery(String entityName) {
-        String errorMessage = "N+1 query detected for entity: " + entityName;
+    private Optional<String> detectNPlusOneQueries(String entityName) {
+        StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace();
+
+        for (int i = 0; i + 1 < stackTraceElements.length; i++) {
+            StackTraceElement stackTraceElement = stackTraceElements[i];
+
+            if (stackTraceElement.getClassName().indexOf(entityName) == 0) {
+                String errorMessage = "N+1 queries detected on a getter of the entity " + entityName +
+                        "\n    at " + stackTraceElements[i + 1].toString() +
+                        "\n    Hint: Missing Eager fetching configuration on the query that fetches the object of " +
+                        "type " + entityName + "\n";
+                return Optional.of(errorMessage);
+            }
+        }
+
+        return Optional.empty();
+    }
+
+    /**
+     * Log the detected N+1 queries error message or throw an exception depending on the configured error level
+     *
+     * @param errorMessage Error message for the N+1 queries detected
+     */
+    private void logDetectedNPlusOneQueries(String errorMessage) {
         switch (hibernateQueryInterceptorProperties.getErrorLevel()) {
             case INFO:
                 LOGGER.info(errorMessage);
@@ -114,13 +139,13 @@ private void logDetectedNPlusOneQuery(String entityName) {
                 LOGGER.error(errorMessage);
                 break;
             default:
-                throw new NPlusOneQueryException(errorMessage);
+                throw new NPlusOneQueriesException(errorMessage, new Exception(new Throwable()));
         }
     }
 }
 
 class EmptySetSupplier implements Supplier<Set<String>> {
-    public Set<String> get(){
+    public Set<String> get() {
         return new HashSet<>();
     }
 }

src/main/java/com/yannbriancon/interceptor/HibernateQueryInterceptor.java

@@ -14,7 +14,7 @@ enum ErrorLevel {
     }
 
     /**
-     * Error level for the N+1 query detection.
+     * Error level for the N+1 queries detection.
      */
     private ErrorLevel errorLevel = ErrorLevel.ERROR;
 

src/main/java/com/yannbriancon/interceptor/HibernateQueryInterceptorProperties.java

@@ -1,6 +1,6 @@
 package com.yannbriancon.interceptor;
 
-import com.yannbriancon.exception.NPlusOneQueryException;
+import com.yannbriancon.exception.NPlusOneQueriesException;
 import com.yannbriancon.utils.entity.Message;
 import com.yannbriancon.utils.repository.MessageRepository;
 import org.junit.jupiter.api.Test;
@@ -18,34 +18,39 @@
 @RunWith(SpringRunner.class)
 @SpringBootTest("hibernate.query.interceptor.error-level=EXCEPTION")
 @Transactional
-class NPlusOneQueryExceptionTest {
+class NPlusOneQueriesExceptionTest {
 
     @Autowired
     private MessageRepository messageRepository;
 
     @Test
-    void nPlusOneQueryDetection_throwCallbackExceptionWhenFetchingWithoutEntityGraph() {
+    void nPlusOneQueriesDetection_throwCallbackExceptionWhenNPlusOneQueries() {
         // Fetch the 2 messages without the authors
         List<Message> messages = messageRepository.findAll();
 
         try {
-            // Trigger N+1 query
+            // Trigger N+1 queries
             List<String> names = messages.stream()
                     .map(message -> message.getAuthor().getName())
                     .collect(Collectors.toList());
             assert false;
-        } catch (NPlusOneQueryException exception) {
+        } catch (NPlusOneQueriesException exception) {
             assertThat(exception.getMessage())
-                    .isEqualTo("N+1 query detected for entity: com.yannbriancon.utils.entity.User");
+                    .isEqualTo("N+1 queries detected on a getter of the entity com.yannbriancon.utils.entity.User\n" +
+                            "    at com.yannbriancon.interceptor.NPlusOneQueriesExceptionTest" +
+                            ".lambda$nPlusOneQueriesDetection_throwCallbackExceptionWhenNPlusOneQueries$0" +
+                            "(NPlusOneQueriesExceptionTest.java:34)\n" +
+                            "    Hint: Missing Eager fetching configuration on the query " +
+                            "that fetches the object of type com.yannbriancon.utils.entity.User\n");
         }
     }
 
     @Test
-    void nPlusOneQueryDetection_isOkWhenFetchingWithEntityGraph() {
+    void nPlusOneQueriesDetection_isNotThrowingExceptionWhenNoNPlusOneQueries() {
         // Fetch the 2 messages with the authors
         List<Message> messages = messageRepository.getAllBy();
 
-        // Do not trigger N+1 query
+        // Do not trigger N+1 queries
         List<String> names = messages.stream()
                 .map(message -> message.getAuthor().getName())
                 .collect(Collectors.toList());

src/test/java/com/yannbriancon/interceptor/NPlusOneQueryExceptionTest.java renamed to src/test/java/com/yannbriancon/interceptor/NPlusOneQueriesExceptionTest.java

@@ -29,7 +29,7 @@
 @RunWith(MockitoJUnitRunner.class)
 @SpringBootTest
 @Transactional
-class NPlusOneQueryLoggingTest {
+class NPlusOneQueriesLoggingTest {
 
     @Autowired
     private MessageRepository messageRepository;
@@ -47,32 +47,32 @@ public void setup() {
     }
 
     @Test
-    void nPlusOneQueryDetection_isLoggingWhenDetectingNPlusOneQuery() {
+    void nPlusOneQueriesDetection_isLoggingWhenDetectingNPlusOneQueries() {
         // Fetch the 2 messages without the authors
         List<Message> messages = messageRepository.findAll();
 
-        // Trigger N+1 query
+        // The getters trigger N+1 queries
         List<String> names = messages.stream()
                 .map(message -> message.getAuthor().getName())
                 .collect(Collectors.toList());
 
         verify(mockedAppender, times(2)).doAppend(loggingEventCaptor.capture());
 
         LoggingEvent loggingEvent = loggingEventCaptor.getAllValues().get(0);
-        assertThat("N+1 query detected for entity: com.yannbriancon.utils.entity.User")
-                .isEqualTo(loggingEvent.getMessage());
+        assertThat(loggingEvent.getMessage())
+                .isEqualTo("N+1 queries detected on a getter of the entity com.yannbriancon.utils.entity.User\n" +
+                        "    at com.yannbriancon.interceptor.NPlusOneQueriesLoggingTest." +
+                        "lambda$nPlusOneQueriesDetection_isLoggingWhenDetectingNPlusOneQueries$0" +
+                        "(NPlusOneQueriesLoggingTest.java:56)\n" +
+                        "    Hint: Missing Eager fetching configuration on the query that fetches the object of type" +
+                        " com.yannbriancon.utils.entity.User\n");
         assertThat(Level.ERROR).isEqualTo(loggingEvent.getLevel());
     }
 
     @Test
-    void nPlusOneQueryDetection_isNotLoggingWhenNotDetectingNPlusOneQuery() {
-        // Fetch the 2 messages with the authors
-        List<Message> messages = messageRepository.getAllBy();
-
-        // Do not trigger N+1 query
-        List<String> names = messages.stream()
-                .map(message -> message.getAuthor().getName())
-                .collect(Collectors.toList());
+    void nPlusOneQueriesDetection_isNotLoggingWhenNoNPlusOneQueries() {
+        // Fetch the messages and does not trigger N+1 queries
+        messageRepository.findById(1L);
 
         verify(mockedAppender, times(0)).doAppend(any());
     }

src/test/java/com/yannbriancon/interceptor/NPlusOneQueryLoggingTest.java renamed to src/test/java/com/yannbriancon/interceptor/NPlusOneQueriesLoggingTest.java

@@ -33,7 +33,6 @@ void queryCount_isOkWhenCallingRepository() {
         messageRepository.findAll();
 
         assertThat(hibernateQueryInterceptor.getQueryCount()).isEqualTo(1);
-
     }
 
     @Test