Bug 9060: mdsal-trace tooling with getAllUnique() to find Tx leaks 01/62501/1
authorMichael Vorburger <vorburger@redhat.com>
Mon, 28 Aug 2017 11:22:43 +0000 (13:22 +0200)
committerMichael Vorburger <vorburger@redhat.com>
Thu, 31 Aug 2017 14:11:08 +0000 (16:11 +0200)
This is one of a serious of commits which is part of a solution I'm
proposing in order to be able to detect OOM issues such as Bug 9034,
based on using the mdsal-trace DataBroker.

Change-Id: I9cf4d8d9965468d77a0d82455655b9445535f0b0
Signed-off-by: Michael Vorburger <vorburger@redhat.com>
opendaylight/md-sal/mdsal-trace/dom-impl/pom.xml
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/AbstractCloseTracked.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTracked.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedRegistry.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedTrait.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingBroker.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingReadWriteTransaction.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingWriteTransaction.java
opendaylight/md-sal/mdsal-trace/dom-impl/src/test/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/tests/CloseTrackedRegistryTest.java [new file with mode: 0644]

index 08dcd4414bcebb49ccafa54c16edec3b49484efd..c0e40914e78868af5cb55785452071713d52c005 100644 (file)
@@ -69,12 +69,16 @@ and is available at http://www.eclipse.org/legal/epl-v10.html
       <artifactId>junit</artifactId>
       <scope>test</scope>
     </dependency>
-
     <dependency>
       <groupId>org.mockito</groupId>
       <artifactId>mockito-core</artifactId>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>com.google.truth</groupId>
+      <artifactId>truth</artifactId>
+      <scope>test</scope>
+    </dependency>
   </dependencies>
     <build>
     <plugins>
index 5673c8e793df9e2370c88e36d8398537d7abe87b..59dbf5749de456c1e2c723a9c96f7089f3fe1512 100644 (file)
@@ -33,7 +33,7 @@ public abstract class AbstractCloseTracked<T extends AbstractCloseTracked<T>> im
     }
 
     @Override
-    public @Nullable Throwable getAllocationContext() {
-        return closeTracker.getAllocationContext();
+    public @Nullable StackTraceElement[] getAllocationContextStackTrace() {
+        return closeTracker.getAllocationContextStackTrace();
     }
 }
index 6d8524fb3d513d5554e566f04f2be3dc301da3cb..1febe153eace20b415bde54d8b90278545de2bd1 100644 (file)
@@ -11,7 +11,7 @@ import java.time.Instant;
 import javax.annotation.Nullable;
 
 /**
- * Object which can track where it has been created, and if it has been correctly closed.
+ * Object which can track where it has been created, and if it has been correctly "closed".
  *
  * <p>Includes preserving the context of the call stack which created this object, and the instant it was created.
  *
@@ -21,6 +21,6 @@ public interface CloseTracked<T extends CloseTracked<T>> {
 
     Instant getObjectCreated();
 
-    @Nullable Throwable getAllocationContext();
+    @Nullable StackTraceElement[] getAllocationContextStackTrace();
 
 }
index 9364a57ae0e6765f6d6b1aedf840385084d2badd..7689831644585c9af13fdd661abe6862c4df4ea1 100644 (file)
@@ -7,6 +7,12 @@
  */
 package org.opendaylight.controller.md.sal.trace.closetracker.impl;
 
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.HashSet;
+import java.util.List;
+import java.util.Map;
 import java.util.Set;
 import java.util.concurrent.ConcurrentSkipListSet;
 import javax.annotation.concurrent.ThreadSafe;
@@ -24,7 +30,7 @@ public class CloseTrackedRegistry<T extends CloseTracked<T>> {
     private final @SuppressWarnings("unused") String createDescription;
 
     private final Set<CloseTracked<T>> tracked = new ConcurrentSkipListSet<>(
-        (o1, o2) -> o1.getObjectCreated().compareTo(o2.getObjectCreated()));
+        (o1, o2) -> Integer.compare(System.identityHashCode(o1), System.identityHashCode(o2)));
 
     private final boolean isDebugContextEnabled;
 
@@ -62,8 +68,24 @@ public class CloseTrackedRegistry<T extends CloseTracked<T>> {
         tracked.remove(closeTracked);
     }
 
-    // TODO Later add methods to dump & query what's not closed, by creation time, incl. creation stack trace
-
-    // TODO we could even support add/close of Object instead of CloseTracked, by creating a wrapper?
+    /**
+     * Creates and returns a "report" of (currently) tracked but not (yet) closed
+     * instances.
+     *
+     * @return Map where key is the StackTraceElement[] identifying a unique
+     *         allocation contexts (or an empty List if debugContextEnabled is false),
+     *         and value is the number of open instances created at that point.
+     */
+    public Map<List<StackTraceElement>, Long> getAllUnique() {
+        Map<List<StackTraceElement>,Long> mapToReturn = new HashMap<>();
+        Set<CloseTracked<T>> copyOfTracked = new HashSet<>(tracked);
+        for (CloseTracked<T> closeTracked : copyOfTracked) {
+            final StackTraceElement[] stackTraceArray = closeTracked.getAllocationContextStackTrace();
+            List<StackTraceElement> stackTraceElements =
+                    stackTraceArray != null ? Arrays.asList(stackTraceArray) : Collections.emptyList();
+            mapToReturn.merge(stackTraceElements, 1L, (oldValue, value) -> oldValue + 1);
+        }
+        return mapToReturn;
+    }
 
 }
index 9f2237d26924e5442851affc90c54a0458303691..f76eeb17c60136f3587b58ff5ae03ed4b37ec673 100644 (file)
@@ -44,8 +44,8 @@ public class CloseTrackedTrait<T extends CloseTracked<T>> implements CloseTracke
     }
 
     @Override
-    public Throwable getAllocationContext() {
-        return allocationContext;
+    public StackTraceElement[] getAllocationContextStackTrace() {
+        return allocationContext != null ? allocationContext.getStackTrace() : null;
     }
 
     public void removeFromTrackedRegistry() {
index 2e16b0ca0ff45736155ffad14a5d0e3dd2724fda..c01c1d9cd3b36bae78ecb03c0bf2fc00173091ef 100644 (file)
@@ -46,13 +46,18 @@ import org.slf4j.LoggerFactory;
  * the objects themselves, as well as the stack trace of the call invoking the registration or write operation.
  * It works by operating as a "bump on the stack" between the application and actual DataBroker, intercepting write
  * and registration calls and writing to the log.
+ *
+ * <p>In addition, it (optionally) can also keep track of the stack trace of all new transaction allocations
+ * (including TransactionChains, and transactions created in turn from them), in order to detect and report leaks
+ *  results from transactions which were not closed.
+ *
  * <h1>Wiring:</h1>
  * TracingBroker is designed to be easy to use. In fact, for bundles using Blueprint to inject their DataBroker
  * TracingBroker can be used without modifying your code at all in two simple steps:
  * <ol>
  * <li>
  * Simply add the dependency "mdsaltrace-features" to
- * your karaf pom:
+ * your Karaf pom:
  * <pre>
  * {@code
  *  <dependency>
index 68c4786317abfb32d1a3d21e9dd9f8fb1e80577c..52f1dab509b012bdf3de0ce8e5f156946cf76c40 100644 (file)
@@ -73,7 +73,7 @@ class TracingReadWriteTransaction
     }
 
     @Override
-    public Throwable getAllocationContext() {
-        return closeTracker.getAllocationContext();
+    public StackTraceElement[] getAllocationContextStackTrace() {
+        return closeTracker.getAllocationContextStackTrace();
     }
 }
index 123129ce156eeb08781987cf5e4a848f1d46cb52..719944ad77a3322830a6d514291b892547a7660b 100644 (file)
@@ -53,8 +53,8 @@ class TracingWriteTransaction extends AbstractTracingWriteTransaction
     }
 
     @Override
-    public Throwable getAllocationContext() {
-        return closeTracker.getAllocationContext();
+    public StackTraceElement[] getAllocationContextStackTrace() {
+        return closeTracker.getAllocationContextStackTrace();
     }
 
 }
diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/test/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/tests/CloseTrackedRegistryTest.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/test/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/tests/CloseTrackedRegistryTest.java
new file mode 100644 (file)
index 0000000..ba34cbf
--- /dev/null
@@ -0,0 +1,87 @@
+/*
+ * Copyright (c) 2017 Red Hat, Inc. and others. All rights reserved.
+ *
+ * This program and the accompanying materials are made available under the
+ * terms of the Eclipse Public License v1.0 which accompanies this distribution,
+ * and is available at http://www.eclipse.org/legal/epl-v10.html
+ */
+package org.opendaylight.controller.md.sal.trace.closetracker.impl.tests;
+
+import static com.google.common.truth.Truth.assertThat;
+import static org.junit.Assert.fail;
+
+import java.util.List;
+import java.util.Map;
+import java.util.function.Predicate;
+import org.junit.Test;
+import org.opendaylight.controller.md.sal.trace.closetracker.impl.AbstractCloseTracked;
+import org.opendaylight.controller.md.sal.trace.closetracker.impl.CloseTrackedRegistry;
+
+public class CloseTrackedRegistryTest {
+
+    private static class SomethingClosable extends AbstractCloseTracked<SomethingClosable> implements AutoCloseable {
+        SomethingClosable(CloseTrackedRegistry<SomethingClosable> transactionChainRegistry) {
+            super(transactionChainRegistry);
+        }
+
+        @Override
+        public void close() {
+            removeFromTrackedRegistry();
+        }
+    }
+
+    @Test
+    public void testDuplicateAllocationContexts() {
+        final CloseTrackedRegistry<SomethingClosable> registry =
+                new CloseTrackedRegistry<>(this, "testDuplicateAllocationContexts", true);
+
+        for (int i = 0; i < 100; i++) {
+            SomethingClosable isClosedManyTimes = new SomethingClosable(registry);
+            isClosedManyTimes.close();
+            someOtherMethodWhichDoesNotClose(registry);
+        }
+        @SuppressWarnings({ "resource", "unused" })
+        SomethingClosable forgotToCloseOnce = new SomethingClosable(registry);
+
+        Map<List<StackTraceElement>, Long> uniqueNonClosed = registry.getAllUnique();
+        assertThat(uniqueNonClosed.values()).containsExactly(100L, 1L);
+        uniqueNonClosed.forEach((stackTraceElements, occurrences) -> {
+            if (occurrences == 100) {
+                assertThatIterableContains(stackTraceElements,
+                    element -> element.getMethodName().equals("someOtherMethodWhichDoesNotClose"));
+            } else { // occurrences == 1
+                assertThatIterableContains(stackTraceElements,
+                    element -> element.getMethodName().equals("testDuplicateAllocationContexts"));
+            }
+        });
+        // one of the two has a StackTraceElement containing
+    }
+
+    // Something like this really should be in Google Truth...
+    private <T> void assertThatIterableContains(Iterable<T> iterable, Predicate<T> predicate) {
+        for (T element : iterable) {
+            if (predicate.test(element)) {
+                return;
+            }
+        }
+        fail("Iterable did not contain any element matching predicate");
+    }
+
+    @SuppressWarnings({ "resource", "unused" })
+    private void someOtherMethodWhichDoesNotClose(CloseTrackedRegistry<SomethingClosable> registry) {
+        new SomethingClosable(registry);
+    }
+
+    @Test
+    @SuppressWarnings({ "unused", "resource" })
+    public void testDebugContextDisabled() {
+        final CloseTrackedRegistry<SomethingClosable> debugContextDisabledRegistry =
+                new CloseTrackedRegistry<>(this, "testDebugContextDisabled", false);
+
+        SomethingClosable forgotToCloseOnce = new SomethingClosable(debugContextDisabledRegistry);
+
+        assertThat(debugContextDisabledRegistry.getAllUnique()).hasSize(1);
+        assertThat(debugContextDisabledRegistry.getAllUnique().values().iterator().next()).isEqualTo(1);
+        assertThat(debugContextDisabledRegistry.getAllUnique().keySet().iterator().next()).isEmpty();
+    }
+}