From 0792888092341cbb7db5f851a5e3bcbca9609e73 Mon Sep 17 00:00:00 2001 From: Michael Vorburger Date: Mon, 28 Aug 2017 13:22:43 +0200 Subject: [PATCH] Bug 9060: mdsal-trace tooling with getAllUnique() to find Tx leaks 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 --- .../md-sal/mdsal-trace/dom-impl/pom.xml | 6 +- .../impl/AbstractCloseTracked.java | 4 +- .../trace/closetracker/impl/CloseTracked.java | 4 +- .../impl/CloseTrackedRegistry.java | 30 ++++++- .../closetracker/impl/CloseTrackedTrait.java | 4 +- .../md/sal/trace/dom/impl/TracingBroker.java | 7 +- .../dom/impl/TracingReadWriteTransaction.java | 4 +- .../dom/impl/TracingWriteTransaction.java | 4 +- .../impl/tests/CloseTrackedRegistryTest.java | 87 +++++++++++++++++++ 9 files changed, 134 insertions(+), 16 deletions(-) create mode 100644 opendaylight/md-sal/mdsal-trace/dom-impl/src/test/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/tests/CloseTrackedRegistryTest.java diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/pom.xml b/opendaylight/md-sal/mdsal-trace/dom-impl/pom.xml index 34b125934b..969e8c61ea 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/pom.xml +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/pom.xml @@ -69,12 +69,16 @@ and is available at http://www.eclipse.org/legal/epl-v10.html junit test - org.mockito mockito-core test + + com.google.truth + truth + test + diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/AbstractCloseTracked.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/AbstractCloseTracked.java index 5673c8e793..59dbf5749d 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/AbstractCloseTracked.java +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/AbstractCloseTracked.java @@ -33,7 +33,7 @@ public abstract class AbstractCloseTracked> im } @Override - public @Nullable Throwable getAllocationContext() { - return closeTracker.getAllocationContext(); + public @Nullable StackTraceElement[] getAllocationContextStackTrace() { + return closeTracker.getAllocationContextStackTrace(); } } diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTracked.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTracked.java index 6d8524fb3d..1febe153ea 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTracked.java +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTracked.java @@ -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". * *

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> { Instant getObjectCreated(); - @Nullable Throwable getAllocationContext(); + @Nullable StackTraceElement[] getAllocationContextStackTrace(); } diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedRegistry.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedRegistry.java index 9364a57ae0..7689831644 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedRegistry.java +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedRegistry.java @@ -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> { private final @SuppressWarnings("unused") String createDescription; private final Set> 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> { 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, Long> getAllUnique() { + Map,Long> mapToReturn = new HashMap<>(); + Set> copyOfTracked = new HashSet<>(tracked); + for (CloseTracked closeTracked : copyOfTracked) { + final StackTraceElement[] stackTraceArray = closeTracked.getAllocationContextStackTrace(); + List stackTraceElements = + stackTraceArray != null ? Arrays.asList(stackTraceArray) : Collections.emptyList(); + mapToReturn.merge(stackTraceElements, 1L, (oldValue, value) -> oldValue + 1); + } + return mapToReturn; + } } diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedTrait.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedTrait.java index 9f2237d269..f76eeb17c6 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedTrait.java +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/CloseTrackedTrait.java @@ -44,8 +44,8 @@ public class CloseTrackedTrait> implements CloseTracke } @Override - public Throwable getAllocationContext() { - return allocationContext; + public StackTraceElement[] getAllocationContextStackTrace() { + return allocationContext != null ? allocationContext.getStackTrace() : null; } public void removeFromTrackedRegistry() { diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingBroker.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingBroker.java index 2e16b0ca0f..c01c1d9cd3 100644 --- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingBroker.java +++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingBroker.java @@ -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. + * + *

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. + * *

Wiring:

* 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: *
    *
  1. * Simply add the dependency "mdsaltrace-features" to - * your karaf pom: + * your Karaf pom: * 
      * {@code
  *  
diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingReadWriteTransaction.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingReadWriteTransaction.java
index 68c4786317..52f1dab509 100644
--- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingReadWriteTransaction.java
+++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingReadWriteTransaction.java
@@ -73,7 +73,7 @@ class TracingReadWriteTransaction
     }
 
     @Override
-    public Throwable getAllocationContext() {
-        return closeTracker.getAllocationContext();
+    public StackTraceElement[] getAllocationContextStackTrace() {
+        return closeTracker.getAllocationContextStackTrace();
     }
 }
diff --git a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingWriteTransaction.java b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingWriteTransaction.java
index 123129ce15..719944ad77 100644
--- a/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingWriteTransaction.java
+++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/main/java/org/opendaylight/controller/md/sal/trace/dom/impl/TracingWriteTransaction.java
@@ -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
index 0000000000..ba34cbf28c
--- /dev/null
+++ b/opendaylight/md-sal/mdsal-trace/dom-impl/src/test/java/org/opendaylight/controller/md/sal/trace/closetracker/impl/tests/CloseTrackedRegistryTest.java
@@ -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 implements AutoCloseable {
+        SomethingClosable(CloseTrackedRegistry transactionChainRegistry) {
+            super(transactionChainRegistry);
+        }
+
+        @Override
+        public void close() {
+            removeFromTrackedRegistry();
+        }
+    }
+
+    @Test
+    public void testDuplicateAllocationContexts() {
+        final CloseTrackedRegistry 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, 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  void assertThatIterableContains(Iterable iterable, Predicate 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 registry) {
+        new SomethingClosable(registry);
+    }
+
+    @Test
+    @SuppressWarnings({ "unused", "resource" })
+    public void testDebugContextDisabled() {
+        final CloseTrackedRegistry 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();
+    }
+}
-- 
2.36.6