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 <robert.varga@pantheon.tech>
(cherry picked from commit c7fb53c205eddf3324a686b024e600480410fdb1)

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 5e5d0f16cd220759c7ad3d1a99dfa8e6c8f61f06..80ba952abb926fff45d9864bf521d59925aea911 100644 (file)
--- 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<Modification> modifications) {
+    void applyModifications(final List<Modification> 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 08609d5953ed8792788cca061cd85f3ac0a76407..57854e87339ab5af7578f5a05a47e72ce8c04933 100644 (file)
--- 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 bb60c07ed3cb032bf40178a61882ced70f61261c..ba831c6c1d1f3104e478f2d380ec70d9054157f5 100644 (file)
--- 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
@@ -675,7 +675,10 @@ public class ShardDataTree extends ShardDataTreeTransactionParent {
     ShardDataTreeCohort finishTransaction(final ReadWriteShardDataTreeTransaction transaction,
             final java.util.Optional<SortedSet<String>> 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);
     }
@@ -933,11 +936,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;
@@ -954,7 +959,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);