From c7fb53c205eddf3324a686b024e600480410fdb1 Mon Sep 17 00:00:00 2001 From: Robert Varga Date: Mon, 1 Jul 2019 08:50:24 +0200 Subject: [PATCH] Add transaction debugs This adds a few debug messages allowing logs to be introspected to see the timing of readying/applying transactions. Change-Id: I1dde184023a034c6a0fa30e9a3898ab65db2decc Signed-off-by: Robert Varga --- .../controller/cluster/datastore/CohortEntry.java | 9 ++++++++- .../cluster/datastore/ShardCommitCoordinator.java | 4 ++-- .../controller/cluster/datastore/ShardDataTree.java | 9 +++++++-- 3 files changed, 17 insertions(+), 5 deletions(-) diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/CohortEntry.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/CohortEntry.java index 5e5d0f16cd..80ba952abb 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/CohortEntry.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/CohortEntry.java @@ -11,6 +11,7 @@ import akka.actor.ActorRef; import com.google.common.base.Preconditions; import com.google.common.primitives.UnsignedLong; import com.google.common.util.concurrent.FutureCallback; +import java.util.List; import java.util.Optional; import java.util.SortedSet; import org.opendaylight.controller.cluster.access.concepts.TransactionIdentifier; @@ -26,6 +27,7 @@ final class CohortEntry { private RuntimeException lastBatchedModificationsException; private int totalBatchedModificationsReceived; + private int totalOperationsProcessed; private ShardDataTreeCohort cohort; private boolean doImmediateCommit; private ActorRef replySender; @@ -77,14 +79,19 @@ final class CohortEntry { return totalBatchedModificationsReceived; } + int getTotalOperationsProcessed() { + return totalOperationsProcessed; + } + RuntimeException getLastBatchedModificationsException() { return lastBatchedModificationsException; } @SuppressWarnings("checkstyle:IllegalCatch") - void applyModifications(final Iterable modifications) { + void applyModifications(final List modifications) { totalBatchedModificationsReceived++; if (lastBatchedModificationsException == null) { + totalOperationsProcessed += modifications.size(); for (Modification modification : modifications) { try { modification.apply(transaction.getSnapshot()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardCommitCoordinator.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardCommitCoordinator.java index a7ba04f25d..ad99fce946 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardCommitCoordinator.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardCommitCoordinator.java @@ -156,8 +156,8 @@ final class ShardCommitCoordinator { } if (log.isDebugEnabled()) { - log.debug("{}: Readying Tx {}, client version {}", name, - batched.getTransactionId(), batched.getVersion()); + log.debug("{}: Readying Tx {} of {} operations, client version {}", name, + batched.getTransactionId(), cohortEntry.getTotalOperationsProcessed(), batched.getVersion()); } cohortEntry.setDoImmediateCommit(batched.isDoCommitOnReady()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardDataTree.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardDataTree.java index c829c035da..32e8f9579c 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardDataTree.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardDataTree.java @@ -676,7 +676,10 @@ public class ShardDataTree extends ShardDataTreeTransactionParent { ShardDataTreeCohort finishTransaction(final ReadWriteShardDataTreeTransaction transaction, final java.util.Optional> participatingShardNames) { final DataTreeModification snapshot = transaction.getSnapshot(); + final TransactionIdentifier id = transaction.getIdentifier(); + LOG.debug("{}: readying transaction {}", logContext, id); snapshot.ready(); + LOG.debug("{}: transaction {} ready", logContext, id); return createReadyCohort(transaction.getIdentifier(), snapshot, participatingShardNames); } @@ -934,11 +937,13 @@ public class ShardDataTree extends ShardDataTreeTransactionParent { final SimpleShardDataTreeCohort current = entry.cohort; Verify.verify(cohort.equals(current), "Attempted to pre-commit %s while %s is pending", cohort, current); - LOG.debug("{}: Preparing transaction {}", logContext, current.getIdentifier()); + final TransactionIdentifier currentId = current.getIdentifier(); + LOG.debug("{}: Preparing transaction {}", logContext, currentId); final DataTreeCandidateTip candidate; try { candidate = tip.prepare(cohort.getDataTreeModification()); + LOG.debug("{}: Transaction {} candidate ready", logContext, currentId); } catch (RuntimeException e) { failPreCommit(e); return; @@ -955,7 +960,7 @@ public class ShardDataTree extends ShardDataTreeTransactionParent { pendingTransactions.remove(); pendingCommits.add(entry); - LOG.debug("{}: Transaction {} prepared", logContext, current.getIdentifier()); + LOG.debug("{}: Transaction {} prepared", logContext, currentId); cohort.successfulPreCommit(candidate); -- 2.36.6