From 233db109dea38ed45ca3c48eba04f302e38a9139 Mon Sep 17 00:00:00 2001 From: Tom Pantelis Date: Wed, 27 May 2015 02:03:20 -0400 Subject: [PATCH] Bug 3376: Add debug context for CDS transactions Added a new setting, transaction-context-debug-enabled, to the config yang to enable/disable debug context that outputs the call site trace for TransactionProxy instances for failed transactions. Change-Id: I8b1a393871be4fa076054681c62c14fd68dc74b7 Signed-off-by: Tom Pantelis (cherry picked from commit 1ae90cd1a9a8000a66942e38a4d1c13d3630c4f8) --- .../cluster/datastore/DatastoreContext.java | 11 +++ .../DebugThreePhaseCommitCohort.java | 89 +++++++++++++++++++ .../cluster/datastore/TransactionProxy.java | 7 +- .../mbeans/DatastoreConfigurationMXBean.java | 2 + .../DatastoreConfigurationMXBeanImpl.java | 5 ++ ...tributedConfigDataStoreProviderModule.java | 1 + ...tedOperationalDataStoreProviderModule.java | 1 + .../yang/distributed-datastore-provider.yang | 15 +++- .../DebugThreePhaseCommitCohortTest.java | 80 +++++++++++++++++ .../datastore/TransactionProxyTest.java | 19 ++++ 10 files changed, 224 insertions(+), 6 deletions(-) create mode 100644 opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java create mode 100644 opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DatastoreContext.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DatastoreContext.java index 2f323aafd3..4140d3323b 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DatastoreContext.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DatastoreContext.java @@ -66,6 +66,7 @@ public class DatastoreContext { private int shardBatchedModificationCount = DEFAULT_SHARD_BATCHED_MODIFICATION_COUNT; private boolean writeOnlyTransactionOptimizationsEnabled = true; private long shardCommitQueueExpiryTimeoutInMillis = DEFAULT_SHARD_COMMIT_QUEUE_EXPIRY_TIMEOUT_IN_MS; + private boolean transactionDebugContextEnabled = false; public static Set getGlobalDatastoreTypes() { return globalDatastoreTypes; @@ -96,6 +97,7 @@ public class DatastoreContext { this.shardBatchedModificationCount = other.shardBatchedModificationCount; this.writeOnlyTransactionOptimizationsEnabled = other.writeOnlyTransactionOptimizationsEnabled; this.shardCommitQueueExpiryTimeoutInMillis = other.shardCommitQueueExpiryTimeoutInMillis; + this.transactionDebugContextEnabled = other.transactionDebugContextEnabled; setShardJournalRecoveryLogBatchSize(other.raftConfig.getJournalRecoveryLogBatchSize()); setSnapshotBatchCount(other.raftConfig.getSnapshotBatchCount()); @@ -208,6 +210,10 @@ public class DatastoreContext { return shardCommitQueueExpiryTimeoutInMillis; } + public boolean isTransactionDebugContextEnabled() { + return transactionDebugContextEnabled; + } + public static class Builder { private final DatastoreContext datastoreContext; private int maxShardDataChangeExecutorPoolSize = @@ -364,6 +370,11 @@ public class DatastoreContext { return this; } + public Builder transactionDebugContextEnabled(boolean value) { + datastoreContext.transactionDebugContextEnabled = value; + return this; + } + public Builder maxShardDataChangeExecutorPoolSize(int maxShardDataChangeExecutorPoolSize) { this.maxShardDataChangeExecutorPoolSize = maxShardDataChangeExecutorPoolSize; return this; diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java new file mode 100644 index 0000000000..9a15de8d06 --- /dev/null +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java @@ -0,0 +1,89 @@ +/* + * Copyright (c) 2015 Brocade Communications Systems, 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.cluster.datastore; + +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.Preconditions; +import com.google.common.util.concurrent.FutureCallback; +import com.google.common.util.concurrent.Futures; +import com.google.common.util.concurrent.ListenableFuture; +import java.util.List; +import org.opendaylight.controller.cluster.datastore.identifiers.TransactionIdentifier; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import scala.concurrent.Future; + +/** + * An AbstractThreePhaseCommitCohort implementation used for debugging. If a failure occurs, the transaction + * call site is printed. + * + * @author Thomas Pantelis + */ +class DebugThreePhaseCommitCohort extends AbstractThreePhaseCommitCohort { + private static final Logger LOG = LoggerFactory.getLogger(DebugThreePhaseCommitCohort.class); + + private final AbstractThreePhaseCommitCohort delegate; + private final Throwable debugContext; + private final TransactionIdentifier transactionId; + private Logger log = LOG; + + DebugThreePhaseCommitCohort(TransactionIdentifier transactionId, AbstractThreePhaseCommitCohort delegate, + Throwable debugContext) { + this.delegate = Preconditions.checkNotNull(delegate); + this.debugContext = Preconditions.checkNotNull(debugContext); + this.transactionId = Preconditions.checkNotNull(transactionId); + } + + private ListenableFuture addFutureCallback(ListenableFuture future) { + Futures.addCallback(future, new FutureCallback() { + @Override + public void onSuccess(V result) { + // no-op + } + + @Override + public void onFailure(Throwable t) { + log.warn("Transaction {} failed with error \"{}\" - was allocated in the following context", + transactionId, t, debugContext); + } + }); + + return future; + } + + @Override + public ListenableFuture canCommit() { + return addFutureCallback(delegate.canCommit()); + } + + @Override + public ListenableFuture preCommit() { + return addFutureCallback(delegate.preCommit()); + } + + @Override + public ListenableFuture commit() { + return addFutureCallback(delegate.commit()); + } + + @Override + public ListenableFuture abort() { + return delegate.abort(); + } + + @SuppressWarnings({ "rawtypes", "unchecked" }) + @Override + List> getCohortFutures() { + return ((AbstractThreePhaseCommitCohort)delegate).getCohortFutures(); + } + + @VisibleForTesting + void setLogger(Logger log) { + this.log = log; + } +} diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java index eca930a03d..e7a00042e4 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java @@ -62,7 +62,8 @@ public class TransactionProxy extends AbstractDOMStoreTransaction txContextFactory, final TransactionType type) { - super(txContextFactory.nextIdentifier(), false); + super(txContextFactory.nextIdentifier(), txContextFactory.getActorContext().getDatastoreContext() + .isTransactionDebugContextEnabled()); this.txContextFactory = txContextFactory; this.type = Preconditions.checkNotNull(type); @@ -255,7 +256,9 @@ public class TransactionProxy extends AbstractDOMStoreTransaction createSingleCommitCohort(final String shardName, diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBean.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBean.java index 981be366d0..daf006c3d6 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBean.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBean.java @@ -44,6 +44,8 @@ public interface DatastoreConfigurationMXBean { long getTransactionCreationInitialRateLimit(); + boolean getTransactionContextDebugEnabled(); + int getMaxShardDataChangeExecutorPoolSize(); int getMaxShardDataChangeExecutorQueueSize(); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBeanImpl.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBeanImpl.java index 261b93de56..b5f01aeedf 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBeanImpl.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBeanImpl.java @@ -104,6 +104,11 @@ public class DatastoreConfigurationMXBeanImpl extends AbstractMXBean implements return context.getTransactionCreationInitialRateLimit(); } + @Override + public boolean getTransactionContextDebugEnabled() { + return context.isTransactionDebugContextEnabled(); + } + @Override public int getMaxShardDataChangeExecutorPoolSize() { return context.getDataStoreProperties().getMaxDataChangeExecutorPoolSize(); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedConfigDataStoreProviderModule.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedConfigDataStoreProviderModule.java index 539797e659..cd27d1df79 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedConfigDataStoreProviderModule.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedConfigDataStoreProviderModule.java @@ -66,6 +66,7 @@ public class DistributedConfigDataStoreProviderModule extends .shardBatchedModificationCount(props.getShardBatchedModificationCount().getValue().intValue()) .shardCommitQueueExpiryTimeoutInSeconds( props.getShardCommitQueueExpiryTimeoutInSeconds().getValue().intValue()) + .transactionDebugContextEnabled(props.getTransactionDebugContextEnabled()) .build(); return DistributedDataStoreFactory.createInstance(getConfigSchemaServiceDependency(), diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedOperationalDataStoreProviderModule.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedOperationalDataStoreProviderModule.java index 45ed184de3..1c94acfca1 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedOperationalDataStoreProviderModule.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedOperationalDataStoreProviderModule.java @@ -67,6 +67,7 @@ public class DistributedOperationalDataStoreProviderModule extends .shardBatchedModificationCount(props.getShardBatchedModificationCount().getValue().intValue()) .shardCommitQueueExpiryTimeoutInSeconds( props.getShardCommitQueueExpiryTimeoutInSeconds().getValue().intValue()) + .transactionDebugContextEnabled(props.getTransactionDebugContextEnabled()) .build(); return DistributedDataStoreFactory.createInstance(getOperationalSchemaServiceDependency(), diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/yang/distributed-datastore-provider.yang b/opendaylight/md-sal/sal-distributed-datastore/src/main/yang/distributed-datastore-provider.yang index 3c753d02d5..09125f1b59 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/yang/distributed-datastore-provider.yang +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/yang/distributed-datastore-provider.yang @@ -193,20 +193,27 @@ module distributed-datastore-provider { description "Enable or disable data persistence"; } - leaf shard-isolated-leader-check-interval-in-millis { + leaf shard-isolated-leader-check-interval-in-millis { default 5000; type heartbeat-interval-type; description "The interval at which the leader of the shard will check if its majority followers are active and term itself as isolated"; - } + } - leaf transaction-creation-initial-rate-limit { + leaf transaction-creation-initial-rate-limit { default 100; type non-zero-uint32-type; description "The initial number of transactions per second that are allowed before the data store should begin applying back pressure. This number is only used as an initial guidance, subsequently the datastore measures the latency for a commit and auto-adjusts the rate limit"; - } + } + + leaf transaction-debug-context-enabled { + default false; + type boolean; + description "Enable or disable transaction context debug. This will log the call site trace for + transactions that fail"; + } } // Augments the 'configuration' choice node under modules/module. diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java b/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java new file mode 100644 index 0000000000..4427ee89bf --- /dev/null +++ b/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java @@ -0,0 +1,80 @@ +/* + * Copyright (c) 2015 Brocade Communications Systems, 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.cluster.datastore; + +import static org.junit.Assert.assertSame; +import static org.mockito.Matchers.any; +import static org.mockito.Matchers.anyString; +import static org.mockito.Matchers.same; +import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.reset; +import static org.mockito.Mockito.verify; +import com.google.common.util.concurrent.Futures; +import com.google.common.util.concurrent.ListenableFuture; +import java.util.ArrayList; +import java.util.List; +import org.junit.Test; +import org.opendaylight.controller.cluster.datastore.identifiers.TransactionIdentifier; +import org.slf4j.Logger; +import scala.concurrent.Future; + +/** + * Unit tests for DebugThreePhaseCommitCohort. + * + * @author Thomas Pantelis + */ +public class DebugThreePhaseCommitCohortTest { + + @Test + public void test() { + AbstractThreePhaseCommitCohort mockDelegate = mock(AbstractThreePhaseCommitCohort.class); + Exception failure = new Exception("mock failure"); + ListenableFuture expFailedFuture = Futures.immediateFailedFuture(failure); + doReturn(expFailedFuture).when(mockDelegate).canCommit(); + doReturn(expFailedFuture).when(mockDelegate).preCommit(); + doReturn(expFailedFuture).when(mockDelegate).commit(); + + ListenableFuture expAbortFuture = Futures.immediateFuture(null); + doReturn(expAbortFuture).when(mockDelegate).abort(); + + List> expCohortFutures = new ArrayList<>(); + doReturn(expCohortFutures).when(mockDelegate).getCohortFutures(); + + TransactionIdentifier transactionId = TransactionIdentifier.create("1", 1, ""); + Throwable debugContext = new RuntimeException("mock"); + DebugThreePhaseCommitCohort cohort = new DebugThreePhaseCommitCohort(transactionId , mockDelegate , debugContext ); + + Logger mockLogger = mock(Logger.class); + cohort.setLogger(mockLogger); + + assertSame("canCommit", expFailedFuture, cohort.canCommit()); + verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext)); + + reset(mockLogger); + assertSame("preCommit", expFailedFuture, cohort.preCommit()); + verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext)); + + reset(mockLogger); + assertSame("commit", expFailedFuture, cohort.commit()); + verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext)); + + assertSame("abort", expAbortFuture, cohort.abort()); + + assertSame("getCohortFutures", expCohortFutures, cohort.getCohortFutures()); + + reset(mockLogger); + ListenableFuture expSuccessFuture = Futures.immediateFuture(Boolean.TRUE); + doReturn(expSuccessFuture).when(mockDelegate).canCommit(); + + assertSame("canCommit", expSuccessFuture, cohort.canCommit()); + verify(mockLogger, never()).warn(anyString(), any(TransactionIdentifier.class), any(Throwable.class), + any(Throwable.class)); + } +} diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/TransactionProxyTest.java b/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/TransactionProxyTest.java index f19bace5b9..8909e1d312 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/TransactionProxyTest.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/TransactionProxyTest.java @@ -615,6 +615,25 @@ public class TransactionProxyTest extends AbstractTransactionProxyTest { verifyCohortFutures((SingleCommitCohortProxy)ready, TestException.class); } + @Test + public void testReadyWithDebugContextEnabled() throws Exception { + dataStoreContextBuilder.transactionDebugContextEnabled(true); + + ActorRef actorRef = setupActorContextWithInitialCreateTransaction(getSystem(), READ_WRITE); + + expectBatchedModificationsReady(actorRef, true); + + TransactionProxy transactionProxy = new TransactionProxy(mockComponentFactory, READ_WRITE); + + transactionProxy.merge(TestModel.TEST_PATH, ImmutableNodes.containerNode(TestModel.TEST_QNAME)); + + DOMStoreThreePhaseCommitCohort ready = transactionProxy.ready(); + + assertTrue(ready instanceof DebugThreePhaseCommitCohort); + + verifyCohortFutures((DebugThreePhaseCommitCohort)ready, new CommitTransactionReply().toSerializable()); + } + private void testWriteOnlyTxWithFindPrimaryShardFailure(Exception toThrow) throws Exception { doReturn(Futures.failed(toThrow)).when(mockActorContext).findPrimaryShardAsync(anyString()); -- 2.36.6