Merge pull request #11 from yannbriancon/add-detection-of-missing-ent…

…ity-lazy-fetching Add detection of missing entity lazy fetching
yannbriancon · May 10, 2020 · 541d062 · 541d062
2 parents 4908ba0 + bfbf5ca
commit 541d062
Show file tree

Hide file tree

Showing 9 changed files with 287 additions and 41 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -0,0 +1,41 @@
+# Changelog
+All notable changes to this project will be documented in this file.
+
+The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
+and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
+
+## [Unreleased]
+
+## [1.0.3] - 2020-05-10
+### Added
+- Add back a more specific detection of N+1 queries due to missing lazy fetching.
+
+### Changed
+- Make the detection of N+1 queries due to missing eager fetching on the queries more specific.
+
+## [1.0.2] - 2020-05-08
+### Changed
+- Rename N+1 query to plural.
+
+### Removed
+- [BUG FIX] Temporarily remove detection of eager fetching on queries to avoid false positives.
+
+## [1.0.1] - 2015-05-06
+### Changed
+- [BUG FIX] Fix initialisation of ThreadLocal variables to avoid NullPointerExceptions.
+
+## [1.0.0] - 2020-05-01
+### Added
+- Auto detection of N+1  queries
+- Error level configuration by application properties
+
+## [0.1.0] - 2019-12-18
+### Added
+- Feature to count the queries
+
+[Unreleased]: https://github.com/yannbriancon/spring-hibernate-query-utils/compare/v1.0.3...HEAD
+[1.0.3]: https://github.com/yannbriancon/spring-hibernate-query-utils/compare/v1.0.2...v1.0.3
+[1.0.2]: https://github.com/yannbriancon/spring-hibernate-query-utils/compare/v1.0.1...v1.0.2
+[1.0.1]: https://github.com/yannbriancon/spring-hibernate-query-utils/compare/v1.0.0...v1.0.1
+[1.0.0]: https://github.com/yannbriancon/spring-hibernate-query-utils/compare/v0.1.0...v1.0.0
+[0.1.0]: https://github.com/yannbriancon/spring-hibernate-query-utils/tree/v0.1.0
diff --git a/README.md b/README.md
@@ -25,9 +25,9 @@
     Spring Hibernate Query Utils: an easy way of detecting N+1 queries and counting queries in a Spring/Hibernate application 
     <br />
     <br />
-    <a href="https://github.com/yannbriancon/spring-hibernate-query-count/issues">Report Bug</a>
+    <a href="https://github.com/yannbriancon/spring-hibernate-query-utils/issues">Report Bug</a>
     ·
-    <a href="https://github.com/yannbriancon/spring-hibernate-query-count/issues">Request Feature</a>
+    <a href="https://github.com/yannbriancon/spring-hibernate-query-utils/issues">Request Feature</a>
   </p>
 </p>
 
@@ -45,6 +45,7 @@
     * [Detection](#detection)
     * [Configuration](#configuration)
   * [Query Count](#query-count)
+* [Changelog](#changelog)
 * [License](#license)
 * [Contact](#contact)
 
@@ -86,7 +87,7 @@ 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.2</version>
+    <version>1.0.3</version>
 </dependency>
 ```
 
@@ -102,7 +103,13 @@ The N+1 queries detection is enabled by default so no configuration is needed.
 
 Each time N+1 queries are detected in a transaction, a log of level error will be sent.
 
-Here is an example catching the N+1 queries detection error log:
+Two types of N+1 queries are detected:
+
+- N+1 queries caused by a field needed but not eager fetched on a specific query
+
+- N+1 queries caused by an entity field not configured to be fetched lazily
+
+Here is an example catching the error log for the first type of N+1 queries:
 
 ```java
 @RunWith(MockitoJUnitRunner.class)
@@ -126,7 +133,7 @@ class NPlusOneQueriesLoggingTest {
     }
 
     @Test
-    void nPlusOneQueriesDetection_isLoggingWhenDetectingNPlusOneQueries() {
+    void hibernateQueryInterceptor_isDetectingNPlusOneQueriesWhenMissingEagerFetchingOnQuery() {
         // Fetch the 2 messages without the authors
         List<Message> messages = messageRepository.findAll();
 
@@ -141,9 +148,9 @@ class NPlusOneQueriesLoggingTest {
         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" +
+                        "lambda$hibernateQueryInterceptor_isDetectingNPlusOneQueriesWhenMissingEagerFetchingOnQuery$0" +
+                        "(NPlusOneQueriesLoggingTest.java:61)\n" +
+                        "    Hint: Missing Eager fetching configuration on the query that fetched the object of type" +
                         " com.yannbriancon.utils.entity.User\n");
         assertThat(Level.ERROR).isEqualTo(loggingEvent.getLevel());
     }
@@ -225,6 +232,10 @@ public class NotificationResourceIntTest {
 }
 ```
 
+<!-- CHANGELOG -->
+## Changelog
+
+See [`CHANGELOG`][changelog-url] for more information.
 
 
 <!-- LICENSE -->
@@ -239,18 +250,19 @@ Distributed under the MIT License. See [`LICENSE`][license-url] for more informa
 
 [@YBriancon](https://twitter.com/YBriancon) - [email protected]
 
-Project Link: [https://github.com/yannbriancon/spring-hibernate-query-count](https://github.com/yannbriancon/spring-hibernate-query-count)
+Project Link: [https://github.com/yannbriancon/spring-hibernate-query-utils](https://github.com/yannbriancon/spring-hibernate-query-utils)
 
 
 <!-- MARKDOWN LINKS & IMAGES -->
 <!-- https://www.markdownguide.org/basic-syntax/#reference-style-links -->
-[contributors-shield]: https://img.shields.io/github/contributors/yannbriancon/spring-hibernate-query-count.svg?style=flat-square
-[contributors-url]: https://github.com/yannbriancon/spring-hibernate-query-count/graphs/contributors
-[forks-shield]: https://img.shields.io/github/forks/yannbriancon/spring-hibernate-query-count.svg?style=flat-square
-[forks-url]: https://github.com/yannbriancon/spring-hibernate-query-count/network/members
-[stars-shield]: https://img.shields.io/github/stars/yannbriancon/spring-hibernate-query-count.svg?style=flat-square
-[stars-url]: https://github.com/yannbriancon/spring-hibernate-query-count/stargazers
-[issues-shield]: https://img.shields.io/github/issues/yannbriancon/spring-hibernate-query-count.svg?style=flat-square
-[issues-url]: https://github.com/yannbriancon/spring-hibernate-query-count/issues
-[license-shield]: https://img.shields.io/github/license/yannbriancon/spring-hibernate-query-count.svg?style=flat-square
-[license-url]: https://github.com/yannbriancon/spring-hibernate-query-count/blob/master/LICENSE
+[contributors-shield]: https://img.shields.io/github/contributors/yannbriancon/spring-hibernate-query-utils.svg?style=flat-square
+[contributors-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/graphs/contributors
+[forks-shield]: https://img.shields.io/github/forks/yannbriancon/spring-hibernate-query-utils.svg?style=flat-square
+[forks-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/network/members
+[stars-shield]: https://img.shields.io/github/stars/yannbriancon/spring-hibernate-query-utils.svg?style=flat-square
+[stars-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/stargazers
+[issues-shield]: https://img.shields.io/github/issues/yannbriancon/spring-hibernate-query-utils.svg?style=flat-square
+[issues-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/issues
+[license-shield]: https://img.shields.io/github/license/yannbriancon/spring-hibernate-query-utils.svg?style=flat-square
+[license-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/blob/master/LICENSE
+[changelog-url]: https://github.com/yannbriancon/spring-hibernate-query-utils/blob/master/CHANGELOG
diff --git a/pom.xml b/pom.xml
@@ -5,7 +5,7 @@
 
     <groupId>com.yannbriancon</groupId>
     <artifactId>spring-hibernate-query-utils</artifactId>
-    <version>1.0.2</version>
+    <version>1.0.3</version>
     <packaging>jar</packaging>
 
     <name>spring-hibernate-query-utils</name>

diff --git a/src/main/java/com/yannbriancon/interceptor/HibernateQueryInterceptor.java b/src/main/java/com/yannbriancon/interceptor/HibernateQueryInterceptor.java
@@ -10,7 +10,9 @@
 import org.springframework.stereotype.Component;
 
 import java.io.Serializable;
+import java.util.HashMap;
 import java.util.HashSet;
+import java.util.Map;
 import java.util.Optional;
 import java.util.Set;
 import java.util.function.Supplier;
@@ -24,10 +26,16 @@ public class HibernateQueryInterceptor extends EmptyInterceptor {
     private transient ThreadLocal<Set<String>> threadPreviouslyLoadedEntities =
             ThreadLocal.withInitial(new EmptySetSupplier());
 
+    private transient ThreadLocal<Map<String, String>> threadProxyMethodEntityMapping =
+            ThreadLocal.withInitial(new EmptyMapSupplier());
+
     private static final Logger LOGGER = LoggerFactory.getLogger(HibernateQueryInterceptor.class);
 
     private final HibernateQueryInterceptorProperties hibernateQueryInterceptorProperties;
 
+    private final String HIBERNATE_PROXY_PREFIX = "org.hibernate.proxy";
+    private final String PROXY_METHOD_PREFIX = "com.sun.proxy";
+
     public HibernateQueryInterceptor(HibernateQueryInterceptorProperties hibernateQueryInterceptorProperties) {
         this.hibernateQueryInterceptorProperties = hibernateQueryInterceptorProperties;
     }
@@ -70,6 +78,7 @@ public String onPrepareStatement(String sql) {
     @Override
     public void afterTransactionCompletion(Transaction tx) {
         threadPreviouslyLoadedEntities.set(new HashSet<>());
+        threadProxyMethodEntityMapping.set(new HashMap<>());
     }
 
     /**
@@ -83,39 +92,139 @@ public void afterTransactionCompletion(Transaction tx) {
      */
     @Override
     public Object getEntity(String entityName, Serializable id) {
+        detectNPlusOneQueriesOfMissingQueryEagerFetching(entityName, id);
+
+        detectNPlusOneQueriesOfMissingEntityFieldLazyFetching(entityName, id);
+
         Set<String> previouslyLoadedEntities = threadPreviouslyLoadedEntities.get();
 
         if (previouslyLoadedEntities.contains(entityName + id)) {
             previouslyLoadedEntities.remove(entityName + id);
             threadPreviouslyLoadedEntities.set(previouslyLoadedEntities);
-            Optional<String> errorMessage = detectNPlusOneQueries(entityName);
-            errorMessage.ifPresent(this::logDetectedNPlusOneQueries);
+        } else {
+            previouslyLoadedEntities.add(entityName + id);
+            threadPreviouslyLoadedEntities.set(previouslyLoadedEntities);
         }
 
-        previouslyLoadedEntities.add(entityName + id);
-        threadPreviouslyLoadedEntities.set(previouslyLoadedEntities);
-
         return null;
     }
 
     /**
-     * Detect the N+1 queries by checking if the stack trace contains an Hibernate Proxy on the Entity
+     * Detect the N+1 queries caused by a missing eager fetching configuration on a query with a lazy loaded field
+     * <p>
+     * <p>
+     * Detection checks:
+     * - The getEntity was called twice for the couple (entity, id)
+     * <p>
+     * - There is an occurrence of hibernate proxy followed by entity class in the stackTraceElements
+     * Avoid detecting calls to queries like findById and queries with eager fetching on some entity fields
+     *
+     * @param entityName Name of the entity
+     * @param id         Id of the entity objecy
+     * @return Boolean telling whether N+1 queries were detected or not
+     */
+    private boolean detectNPlusOneQueriesOfMissingQueryEagerFetching(String entityName, Serializable id) {
+        Set<String> previouslyLoadedEntities = threadPreviouslyLoadedEntities.get();
+
+        if (!previouslyLoadedEntities.contains(entityName + id)) {
+            return false;
+        }
+
+        // Detect N+1 queries by searching for newest occurrence of Hibernate proxy followed by entity class in stack
+        // elements
+        StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace();
+        StackTraceElement originStackTraceElement = null;
+
+        for (int i = 0; i < stackTraceElements.length - 3; i++) {
+            if (
+                    stackTraceElements[i].getClassName().indexOf(HIBERNATE_PROXY_PREFIX) == 0
+                            && stackTraceElements[i + 1].getClassName().indexOf(entityName) == 0
+            ) {
+                originStackTraceElement = stackTraceElements[i + 2];
+                break;
+            }
+        }
+
+        if (originStackTraceElement == null) {
+            return false;
+        }
+
+        String errorMessage = "N+1 queries detected on a getter of the entity " + entityName +
+                "\n    at " + originStackTraceElement.toString() +
+                "\n    Hint: Missing Eager fetching configuration on the query that fetched the object of " +
+                "type " + entityName + "\n";
+        logDetectedNPlusOneQueries(errorMessage);
+
+        return true;
+    }
+
+    /**
+     * Detect the N+1 queries caused by a missing lazy fetching configuration on an entity field
+     * <p>
+     * Detection checks:
+     * - The getEntity was called twice for the couple (entity, id)
+     * <p>
+     * - The query that triggered the fetching of the entity object was first called for a different entity
+     * Avoid detecting calls to queries like findById
      *
      * @param entityName Name of the entity
-     * @return If N+1 queries detected, return error message corresponding to the N+1 queries
+     * @param id         Id of the entity objecy
+     * @return Boolean telling whether N+1 queries were detected or not
      */
-    private Optional<String> detectNPlusOneQueries(String entityName) {
+    private boolean detectNPlusOneQueriesOfMissingEntityFieldLazyFetching(String entityName, Serializable id) {
+        Optional<String> optionalProxyMethodName = getProxyMethodName();
+        if (!optionalProxyMethodName.isPresent()) {
+            return false;
+        }
+        String proxyMethodName = optionalProxyMethodName.get();
+
+        Set<String> previouslyLoadedEntities = threadPreviouslyLoadedEntities.get();
+        Map<String, String> proxyMethodEntityMapping = threadProxyMethodEntityMapping.get();
+
+        boolean nPlusOneQueriesDetected = false;
+        if (
+                previouslyLoadedEntities.contains(entityName + id)
+                        && proxyMethodEntityMapping.containsKey(proxyMethodName)
+                        && !proxyMethodEntityMapping.get(proxyMethodName).equals(entityName)
+        ) {
+            nPlusOneQueriesDetected = true;
+
+            String errorMessage = "N+1 queries detected on a query for the entity " + entityName;
+
+            // Find origin of the N+1 queries in client package
+            // by getting oldest occurrence of proxy method in stack elements
+            StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace();
+
+            for (int i = stackTraceElements.length - 1; i >= 1; i--) {
+                if (stackTraceElements[i - 1].getClassName().indexOf(PROXY_METHOD_PREFIX) == 0) {
+                    errorMessage += "\n    at " + stackTraceElements[i].toString();
+                    break;
+                }
+            }
+
+            errorMessage += "\n    Hint: Missing Lazy fetching configuration on a field of one of the entities " +
+                    "fetched in the query\n";
+
+            logDetectedNPlusOneQueries(errorMessage);
+        }
+
+        proxyMethodEntityMapping.putIfAbsent(proxyMethodName, entityName);
+        return nPlusOneQueriesDetected;
+    }
+
+    /**
+     * Get the Proxy method name that was called first to know which query triggered the interceptor
+     *
+     * @return Optional of method name if found
+     */
+    private Optional<String> getProxyMethodName() {
         StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace();
 
-        for (int i = 0; i + 1 < stackTraceElements.length; i++) {
+        for (int i = stackTraceElements.length - 1; i >= 0; 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);
+            if (stackTraceElement.getClassName().indexOf("com.sun.proxy") == 0) {
+                return Optional.of(stackTraceElement.getClassName() + stackTraceElement.getMethodName());
             }
         }
 
@@ -149,3 +258,9 @@ public Set<String> get() {
         return new HashSet<>();
     }
 }
+
+class EmptyMapSupplier implements Supplier<Map<String, String>> {
+    public Map<String, String> get() {
+        return new HashMap<>();
+    }
+}
diff --git a/src/test/java/com/yannbriancon/interceptor/NPlusOneQueriesExceptionTest.java b/src/test/java/com/yannbriancon/interceptor/NPlusOneQueriesExceptionTest.java
@@ -41,7 +41,7 @@ void nPlusOneQueriesDetection_throwCallbackExceptionWhenNPlusOneQueries() {
                             ".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");
+                            "that fetched the object of type com.yannbriancon.utils.entity.User\n");
         }
     }