From: Robert Varga <rovarga@cisco.com>
Date: Sun, 9 Mar 2014 10:40:11 +0000 (+0100)
Subject: Cleanup AbstractDataTransaction state changes
X-Git-Tag: autorelease-tag-v20140601202136_82eb3f9~346
X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=commitdiff_plain;h=80bcd6f5ae8541df5590d69aa1b46c1d2692bba1;hp=1a0f15f16de47a6719cf23e4c84252c097ac4cae

Cleanup AbstractDataTransaction state changes

Centralize state to be internal and add time tracking, such that it can
be used in logs and statistics.

Change-Id: Ie4197cd2a10bb6b89931f5ecd9b3cc6dcfbe3011
Signed-off-by: Robert Varga <rovarga@cisco.com>
---

diff --git a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataBroker.java b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataBroker.java
index ed186dcf31..82ce44c5e9 100644
--- a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataBroker.java
+++ b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataBroker.java
@@ -406,7 +406,6 @@ public abstract class AbstractDataBroker<P extends Path<P>, D extends Object, DC
 
     final Future<RpcResult<TransactionStatus>> commit(final AbstractDataTransaction<P, D> transaction) {
         Preconditions.checkNotNull(transaction);
-        transaction.changeStatus(TransactionStatus.SUBMITED);
         final TwoPhaseCommit<P, D, DCL> task = new TwoPhaseCommit<P, D, DCL>(transaction, this);
 
         this.getSubmittedTransactionsCount().getAndIncrement();
diff --git a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataTransaction.java b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataTransaction.java
index 8a5f93ac7f..b030e6cb5f 100644
--- a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataTransaction.java
+++ b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/AbstractDataTransaction.java
@@ -8,6 +8,7 @@
 package org.opendaylight.controller.md.sal.common.impl.service;
 
 import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
 
 import org.opendaylight.controller.md.sal.common.api.TransactionStatus;
 import org.opendaylight.controller.md.sal.common.impl.AbstractDataModification;
@@ -16,32 +17,41 @@ import org.opendaylight.yangtools.yang.common.RpcResult;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import com.google.common.base.Preconditions;
+
 public abstract class AbstractDataTransaction<P extends Path<P>, D extends Object> extends
         AbstractDataModification<P, D> {
     private final static Logger LOG = LoggerFactory.getLogger(AbstractDataTransaction.class);
 
     private final Object identifier;
+    private final long allocationTime;
+    private long readyTime = 0;
+    private long completeTime = 0;
 
-    @Override
-    public Object getIdentifier() {
-        return this.identifier;
-    }
-
-    private TransactionStatus status;
+    private TransactionStatus status = TransactionStatus.NEW;
 
     private final AbstractDataBroker<P, D, ? extends Object> broker;
 
     protected AbstractDataTransaction(final Object identifier,
             final AbstractDataBroker<P, D, ? extends Object> dataBroker) {
         super(dataBroker);
-        this.identifier = identifier;
-        this.broker = dataBroker;
-        this.status = TransactionStatus.NEW;
-        AbstractDataTransaction.LOG.debug("Transaction {} Allocated.", identifier);
+        this.identifier = Preconditions.checkNotNull(identifier);
+        this.broker = Preconditions.checkNotNull(dataBroker);
+        this.allocationTime = System.nanoTime();
+        LOG.debug("Transaction {} Allocated.", identifier);
+    }
+
+    @Override
+    public Object getIdentifier() {
+        return this.identifier;
     }
 
     @Override
     public Future<RpcResult<TransactionStatus>> commit() {
+        readyTime = System.nanoTime();
+        LOG.debug("Transaction {} Ready after {}ms.", identifier, TimeUnit.NANOSECONDS.toMillis(readyTime - allocationTime));
+        changeStatus(TransactionStatus.SUBMITED);
+
         return this.broker.commit(this);
     }
 
@@ -63,8 +73,6 @@ public abstract class AbstractDataTransaction<P extends Path<P>, D extends Objec
         return this.broker.readOperationalData(path);
     }
 
-
-
     @Override
     public int hashCode() {
         final int prime = 31;
@@ -97,10 +105,20 @@ public abstract class AbstractDataTransaction<P extends Path<P>, D extends Objec
 
     protected abstract void onStatusChange(final TransactionStatus status);
 
-    public void changeStatus(final TransactionStatus status) {
-        Object _identifier = this.getIdentifier();
-        AbstractDataTransaction.LOG
-                .debug("Transaction {} transitioned from {} to {}", _identifier, this.status, status);
+    public void succeeded() {
+        this.completeTime = System.nanoTime();
+        LOG.debug("Transaction {} Committed after {}ms.", identifier, TimeUnit.NANOSECONDS.toMillis(completeTime - readyTime));
+        changeStatus(TransactionStatus.COMMITED);
+    }
+
+    public void failed() {
+        this.completeTime = System.nanoTime();
+        LOG.debug("Transaction {} Failed after {}ms.", identifier, TimeUnit.NANOSECONDS.toMillis(completeTime - readyTime));
+        changeStatus(TransactionStatus.FAILED);
+    }
+
+    private void changeStatus(final TransactionStatus status) {
+        LOG.debug("Transaction {} transitioned from {} to {}", getIdentifier(), this.status, status);
         this.status = status;
         this.onStatusChange(status);
     }
diff --git a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/TwoPhaseCommit.java b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/TwoPhaseCommit.java
index e201f8835b..a51dc64816 100644
--- a/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/TwoPhaseCommit.java
+++ b/opendaylight/md-sal/sal-common-impl/src/main/java/org/opendaylight/controller/md/sal/common/impl/service/TwoPhaseCommit.java
@@ -64,7 +64,7 @@ public class TwoPhaseCommit<P extends Path<P>, D extends Object, DCL extends Dat
         // The transaction has no effects, let's just shortcut it
         if (changedPaths.isEmpty()) {
             dataBroker.getFinishedTransactionsCount().getAndIncrement();
-            transaction.changeStatus(TransactionStatus.COMMITED);
+            transaction.succeeded();
 
             log.trace("Transaction: {} Finished successfully (no effects).", transactionId);
 
@@ -98,7 +98,7 @@ public class TwoPhaseCommit<P extends Path<P>, D extends Object, DCL extends Dat
         } catch (Exception e) {
             log.error("Transaction: {} Request Commit failed", transactionId, e);
             dataBroker.getFailedTransactionsCount().getAndIncrement();
-            this.transaction.changeStatus(TransactionStatus.FAILED);
+            this.transaction.failed();
             return this.rollback(handlerTransactions, e);
 
         }
@@ -112,13 +112,13 @@ public class TwoPhaseCommit<P extends Path<P>, D extends Object, DCL extends Dat
         } catch (Exception e) {
             log.error("Transaction: {} Finish Commit failed", transactionId, e);
             dataBroker.getFailedTransactionsCount().getAndIncrement();
-            transaction.changeStatus(TransactionStatus.FAILED);
+            transaction.failed();
             return this.rollback(handlerTransactions, e);
         }
 
 
         dataBroker.getFinishedTransactionsCount().getAndIncrement();
-        transaction.changeStatus(TransactionStatus.COMMITED);
+        transaction.succeeded();
 
         log.trace("Transaction: {} Finished successfully.", transactionId);